Skip to content

Commit

Permalink
Add statusCode to System.Net.Http/RequestStop event
Browse files Browse the repository at this point in the history
  • Loading branch information
@brianrob
brianrob committed Mar 9, 2023
1 parent a8c0d32 commit 003e675
Show file tree
Hide file tree
Showing 3 changed files with 21 additions and 16 deletions.
15 changes: 8 additions & 7 deletions src/libraries/System.Net.Http/src/System/Net/Http/HttpClient.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -227,7 +227,7 @@ private async Task<string> GetStringAsyncCore(HttpRequestMessage request, Cancel
}
finally
{
FinishSend(cts, disposeCts, telemetryStarted, responseContentTelemetryStarted);
FinishSend(cts, disposeCts, response, telemetryStarted, responseContentTelemetryStarted);
}
}

Expand Down Expand Up @@ -306,7 +306,7 @@ private async Task<byte[]> GetByteArrayAsyncCore(HttpRequestMessage request, Can
}
finally
{
FinishSend(cts, disposeCts, telemetryStarted, responseContentTelemetryStarted);
FinishSend(cts, disposeCts, response, telemetryStarted, responseContentTelemetryStarted);
}
}

Expand Down Expand Up @@ -352,7 +352,7 @@ private async Task<Stream> GetStreamAsyncCore(HttpRequestMessage request, Cancel
}
finally
{
FinishSend(cts, disposeCts, telemetryStarted, responseContentTelemetryStarted: false);
FinishSend(cts, disposeCts, response, telemetryStarted, responseContentTelemetryStarted: false);
}
}

Expand Down Expand Up @@ -496,7 +496,7 @@ public HttpResponseMessage Send(HttpRequestMessage request, HttpCompletionOption
}
finally
{
FinishSend(cts, disposeCts, telemetryStarted, responseContentTelemetryStarted);
FinishSend(cts, disposeCts, response, telemetryStarted, responseContentTelemetryStarted);
}
}

Expand Down Expand Up @@ -551,7 +551,7 @@ async Task<HttpResponseMessage> Core(
}
finally
{
FinishSend(cts, disposeCts, telemetryStarted, responseContentTelemetryStarted);
FinishSend(cts, disposeCts, response, telemetryStarted, responseContentTelemetryStarted);
}
}
}
Expand Down Expand Up @@ -642,7 +642,7 @@ private static bool StartSend(HttpRequestMessage request)
return false;
}

private static void FinishSend(CancellationTokenSource cts, bool disposeCts, bool telemetryStarted, bool responseContentTelemetryStarted)
private static void FinishSend(CancellationTokenSource cts, bool disposeCts, HttpResponseMessage? response, bool telemetryStarted, bool responseContentTelemetryStarted)
{
// Log completion.
if (HttpTelemetry.Log.IsEnabled() && telemetryStarted)
Expand All @@ -652,7 +652,8 @@ private static void FinishSend(CancellationTokenSource cts, bool disposeCts, boo
HttpTelemetry.Log.ResponseContentStop();
}

HttpTelemetry.Log.RequestStop();
int statusCode = response != null ? (int)response.StatusCode : -1;
HttpTelemetry.Log.RequestStop(statusCode);
}

// Dispose of the CancellationTokenSource if it was created specially for this request
Expand Down
16 changes: 10 additions & 6 deletions 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 @@ -40,10 +40,11 @@ public virtual HttpResponseMessage Send(HttpRequestMessage request, Cancellation
if (ShouldSendWithTelemetry(request))
{
HttpTelemetry.Log.RequestStart(request);

HttpResponseMessage? response = null;
try
{
return _handler.Send(request, cancellationToken);
response = _handler.Send(request, cancellationToken);
return response;
}
catch when (LogRequestFailed(telemetryStarted: true))
{
Expand All @@ -52,7 +53,8 @@ public virtual HttpResponseMessage Send(HttpRequestMessage request, Cancellation
}
finally
{
HttpTelemetry.Log.RequestStop();
int statusCode = response != null ? (int)response.StatusCode : -1;
HttpTelemetry.Log.RequestStop(statusCode);
}
}
else
Expand All @@ -77,10 +79,11 @@ public virtual Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, C
static async Task<HttpResponseMessage> SendAsyncWithTelemetry(HttpMessageHandler handler, HttpRequestMessage request, CancellationToken cancellationToken)
{
HttpTelemetry.Log.RequestStart(request);

HttpResponseMessage? response = null;
try
{
return await handler.SendAsync(request, cancellationToken).ConfigureAwait(false);
response = await handler.SendAsync(request, cancellationToken).ConfigureAwait(false);
return response;
}
catch when (LogRequestFailed(telemetryStarted: true))
{
Expand All @@ -89,7 +92,8 @@ static async Task<HttpResponseMessage> SendAsyncWithTelemetry(HttpMessageHandler
}
finally
{
HttpTelemetry.Log.RequestStop();
int statusCode = response != null ? (int)response.StatusCode : -1;
HttpTelemetry.Log.RequestStop(statusCode);
}
}
}
Expand Down
6 changes: 3 additions & 3 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 @@ -50,11 +50,11 @@ public void RequestStart(HttpRequestMessage request)
request.VersionPolicy);
}

[Event(2, Level = EventLevel.Informational)]
public void RequestStop()
[Event(2, Level = EventLevel.Informational, Version = 1)]

This comment has been minimized.

Sign in to view

Copy link
@MihaZupan

MihaZupan Mar 10, 2023

Member

Side note re: version, are we expected to update that? I know for example with Kestrel's EventSource, more arguments were added to existing events between .NET releases without changing the version.

This comment has been minimized.

Sign in to view

Copy link
@brianrob

brianrob Mar 10, 2023

Author Member

Yes. It is good practice to increment the version. However, if fields are strictly added at the end of the payload, then it is possible to write a backwards compatible parser, and incrementing the version is not critical.
public void RequestStop(int statusCode)

This comment has been minimized.

Sign in to view

Copy link
@MihaZupan

MihaZupan Mar 10, 2023

Member

it may make sense to move this to ResponseHeadersStop instead. That event will fire closest to when we have a status code available.

In the case of redirects, we may also go through multiple actual requests under the RequestStart/Stop, so we may want that info on ResponseHeadersStop regardless.

There are also cases (mainly redirects again) where that event may have access to the status code, but the caller to HttpClient will not get an HttpResponseMessage object, so RequestStop has nothing to pull that info out of.

This comment has been minimized.

Sign in to view

Copy link
@brianrob

brianrob Mar 10, 2023

Author Member

I will defer to you on this - do you think that this belongs on ResponseHeadersStop? If so, how should consumers handle the case of multiple status codes? Would they also see multiple Restart/Start events?

This comment has been minimized.

Sign in to view

Copy link
@noahfalk

noahfalk Mar 23, 2023

Member

There are also cases (mainly redirects again) where that event may have access to the status code, but the caller to HttpClient will not get an HttpResponseMessage object

Is there a good canonical example of this? Is it something like we send an initial network request that gets a 301 response, followed by a 2nd request to the new location that times out? Are there other reasons HttpClient might not have a response?

Having a status code on RequestStop doesn't appear mutually exclusive with having one ResponseHeadersStop. Is there a downside to doing both? Presumably if telemetry only cares about the final result of a series of redirects it can look at RequestStop, and if it cares about seeing the result of each intermediate response it could look at ResponseHeadersStop.

This comment has been minimized.

Sign in to view

Copy link
@MihaZupan

MihaZupan Mar 23, 2023 •
edited
Loading

Member

how should consumers handle the case of multiple status codes? Would they also see multiple Restart/Start events?

The RequestStart/RequestStop in HttpClient really means "the call to HttpClient.SendAsync started & returned". Unfortunately due to how "middleware" are layered with HttpClient, redirects (or other custom handler logic) will happen inside a single RequestStart/Stop pair. Differentiating such requests is something we could look into improving in the future as well.
For simple cases where you only care about a single status code, the user is free to just consider the last one they observed.

Is there a good canonical example of this? Is it something like we send an initial network request that gets a 301 response, followed by a 2nd request to the new location that times out? Are there other reasons HttpClient might not have a response?

Redirects like you mentioned should be the main case. Another case is "something in a custom HttpMessageHandler threw". E.g. if you have a custom handler that does retries, or maybe reads the response content, you can end up in a situation where the underlying request did get to see the response status code, but the code in HttpClient that logs the start/stop won't see the response object.

Is there a downside to doing both? Presumably if telemetry only cares about the final result of a series of redirects it can look at RequestStop, and if it cares about seeing the result of each intermediate response it could look at ResponseHeadersStop.

I think having it be on RequestStop (in addition to ResponseHeadersStop) would be okay.
I updated the tracking issue to include this as well - #83734.
{
Interlocked.Increment(ref _stoppedRequests);
WriteEvent(eventId: 2);
WriteEvent(eventId: 2, statusCode);
}

[Event(3, Level = EventLevel.Error)]
Expand Down

0 comments on commit 003e675

Please sign in to comment.