Skip to content

Commit

Permalink
Add status code and exception info to System.Net.Http events (#84807)
Browse files Browse the repository at this point in the history
  • Loading branch information
MihaZupan committed May 3, 2023
1 parent 34f40ad commit 809b82e
Show file tree
Hide file tree
Showing 7 changed files with 72 additions and 35 deletions.
18 changes: 9 additions & 9 deletions src/libraries/System.Net.Http/src/System/Net/Http/HttpClient.cs
Original file line number Diff line number Diff line change
Expand Up @@ -224,7 +224,7 @@ private async Task<string> GetStringAsyncCore(HttpRequestMessage request, Cancel
}
finally
{
FinishSend(cts, disposeCts, telemetryStarted, responseContentTelemetryStarted);
FinishSend(response, cts, disposeCts, telemetryStarted, responseContentTelemetryStarted);
}
}

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

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

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

Expand Down Expand Up @@ -548,7 +548,7 @@ async Task<HttpResponseMessage> Core(
}
finally
{
FinishSend(cts, disposeCts, telemetryStarted, responseContentTelemetryStarted);
FinishSend(response, cts, disposeCts, telemetryStarted, responseContentTelemetryStarted);
}
}
}
Expand Down Expand Up @@ -583,8 +583,6 @@ private static bool ShouldBufferResponse(HttpCompletionOption completionOption,

private void HandleFailure(Exception e, bool telemetryStarted, HttpResponseMessage? response, CancellationTokenSource cts, CancellationToken cancellationToken, CancellationTokenSource pendingRequestsCts)
{
LogRequestFailed(telemetryStarted);

response?.Dispose();

Exception? toThrow = null;
Expand Down Expand Up @@ -616,6 +614,8 @@ private void HandleFailure(Exception e, bool telemetryStarted, HttpResponseMessa
e = toThrow = new OperationCanceledException(cancellationToken.IsCancellationRequested ? cancellationToken : cts.Token);
}

LogRequestFailed(e, telemetryStarted);

if (NetEventSource.Log.IsEnabled()) NetEventSource.Error(this, e);

if (toThrow != null)
Expand All @@ -635,7 +635,7 @@ private static bool StartSend(HttpRequestMessage request)
return false;
}

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

HttpTelemetry.Log.RequestStop();
HttpTelemetry.Log.RequestStop(response);
}

// Dispose of the CancellationTokenSource if it was created specially for this request
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -46,18 +46,20 @@ public virtual HttpResponseMessage Send(HttpRequestMessage request, Cancellation
{
HttpTelemetry.Log.RequestStart(request);

HttpResponseMessage? response = null;
try
{
return _handler.Send(request, cancellationToken);
response = _handler.Send(request, cancellationToken);
return response;
}
catch when (LogRequestFailed(telemetryStarted: true))
catch (Exception ex) when (LogRequestFailed(ex, telemetryStarted: true))
{
// Unreachable as LogRequestFailed will return false
throw;
}
finally
{
HttpTelemetry.Log.RequestStop();
HttpTelemetry.Log.RequestStop(response);
}
}
else
Expand Down Expand Up @@ -85,18 +87,20 @@ static async Task<HttpResponseMessage> SendAsyncWithTelemetry(HttpMessageHandler
{
HttpTelemetry.Log.RequestStart(request);

HttpResponseMessage? response = null;
try
{
return await handler.SendAsync(request, cancellationToken).ConfigureAwait(false);
response = await handler.SendAsync(request, cancellationToken).ConfigureAwait(false);
return response;
}
catch when (LogRequestFailed(telemetryStarted: true))
catch (Exception ex) when (LogRequestFailed(ex, telemetryStarted: true))
{
// Unreachable as LogRequestFailed will return false
throw;
}
finally
{
HttpTelemetry.Log.RequestStop();
HttpTelemetry.Log.RequestStop(response);
}
}
}
Expand All @@ -107,11 +111,11 @@ private static bool ShouldSendWithTelemetry(HttpRequestMessage request) =>
request.RequestUri is Uri requestUri &&
requestUri.IsAbsoluteUri;

internal static bool LogRequestFailed(bool telemetryStarted)
internal static bool LogRequestFailed(Exception exception, bool telemetryStarted)
{
if (HttpTelemetry.Log.IsEnabled() && telemetryStarted)
{
HttpTelemetry.Log.RequestFailed();
HttpTelemetry.Log.RequestFailed(exception);
}
return false;
}
Expand Down
34 changes: 25 additions & 9 deletions src/libraries/System.Net.Http/src/System/Net/Http/HttpTelemetry.cs
Original file line number Diff line number Diff line change
Expand Up @@ -48,18 +48,34 @@ public void RequestStart(HttpRequestMessage request)
request.VersionPolicy);
}

[Event(2, Level = EventLevel.Informational)]
public void RequestStop()
[NonEvent]
public void RequestStop(HttpResponseMessage? response)
{
RequestStop(response is null ? -1 : (int)response.StatusCode);
}

[Event(2, Level = EventLevel.Informational, Version = 1)]
private void RequestStop(int statusCode)
{
Interlocked.Increment(ref _stoppedRequests);
WriteEvent(eventId: 2);
WriteEvent(eventId: 2, statusCode);
}

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

if (IsEnabled(EventLevel.Error, EventKeywords.None))
{
RequestFailed(exceptionMessage: exception.Message);
}
}

[Event(3, Level = EventLevel.Error, Version = 1)]
private void RequestFailed(string exceptionMessage)
{
WriteEvent(eventId: 3, exceptionMessage);
}

[Event(4, Level = EventLevel.Informational)]
Expand Down Expand Up @@ -110,10 +126,10 @@ public void ResponseHeadersStart()
WriteEvent(eventId: 11);
}

[Event(12, Level = EventLevel.Informational)]
public void ResponseHeadersStop()
[Event(12, Level = EventLevel.Informational, Version = 1)]
public void ResponseHeadersStop(int statusCode)
{
WriteEvent(eventId: 12);
WriteEvent(eventId: 12, statusCode);
}

[Event(13, Level = EventLevel.Informational)]
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -998,7 +998,8 @@ public async Task ReadResponseHeadersAsync(CancellationToken cancellationToken)
Debug.Assert(!wait);
}

if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.ResponseHeadersStop();
Debug.Assert(_response is not null);
if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.ResponseHeadersStop((int)_response.StatusCode);
}
catch
{
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -669,7 +669,7 @@ public async Task<HttpResponseMessage> SendAsyncCore(HttpRequestMessage request,
ParseHeaderNameValue(this, line.Span, response, isFromTrailer: false);
}

if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.ResponseHeadersStop();
if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.ResponseHeadersStop((int)response.StatusCode);

if (allowExpect100ToContinue != null)
{
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -409,14 +409,25 @@ private static void ValidateStartFailedStopEvents(ConcurrentQueue<(EventWrittenE
Assert.Equal(count, starts.Length);

(EventWrittenEventArgs Event, Guid ActivityId)[] stops = events.Where(e => e.Event.EventName == "RequestStop").ToArray();
Assert.All(stops, stopEvent => Assert.Empty(stopEvent.Event.Payload));
foreach (EventWrittenEventArgs stopEvent in stops.Select(e => e.Event))
{
object payload = Assert.Single(stopEvent.Payload);
int statusCode = Assert.IsType<int>(payload);
Assert.Equal(shouldHaveFailures ? -1 : 200, statusCode);
}

ValidateSameActivityIds(starts, stops);

(EventWrittenEventArgs Event, Guid ActivityId)[] failures = events.Where(e => e.Event.EventName == "RequestFailed").ToArray();
Assert.All(failures, failedEvent => Assert.Empty(failedEvent.Event.Payload));
if (shouldHaveFailures)
{
foreach (EventWrittenEventArgs failedEvent in failures.Select(e => e.Event))
{
object payload = Assert.Single(failedEvent.Payload);
string exceptionMessage = Assert.IsType<string>(payload);
Assert.Equal(new OperationCanceledException().Message, exceptionMessage);
}

ValidateSameActivityIds(starts, failures);
}
else
Expand Down Expand Up @@ -467,8 +478,8 @@ private static void ValidateRequestResponseStartStopEvents(ConcurrentQueue<(Even
foreach (EventWrittenEventArgs requestContentStop in requestContentStops.Select(e => e.Event))
{
object payload = Assert.Single(requestContentStop.Payload);
Assert.True(payload is long);
Assert.Equal(requestContentLength.Value, (long)payload);
long contentLength = Assert.IsType<long>(payload);
Assert.Equal(requestContentLength.Value, contentLength);
}

ValidateSameActivityIds(requestContentStarts, requestContentStops);
Expand All @@ -479,7 +490,12 @@ private static void ValidateRequestResponseStartStopEvents(ConcurrentQueue<(Even

(EventWrittenEventArgs Event, Guid ActivityId)[] responseHeadersStops = events.Where(e => e.Event.EventName == "ResponseHeadersStop").ToArray();
Assert.Equal(count, responseHeadersStops.Length);
Assert.All(responseHeadersStops, r => Assert.Empty(r.Event.Payload));
foreach (EventWrittenEventArgs responseHeadersStop in responseHeadersStops.Select(e => e.Event))
{
object payload = Assert.Single(responseHeadersStop.Payload);
int statusCode = Assert.IsType<int>(payload);
Assert.Equal(200, statusCode);
}

ValidateSameActivityIds(responseHeadersStarts, responseHeadersStops);

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -11,9 +11,9 @@ public class HttpTelemetry

public void RequestStart(HttpRequestMessage request) { }

public void RequestStop() { }
public void RequestStop(HttpResponseMessage response) { }

public void RequestFailed() { }
public void RequestFailed(Exception exception) { }

public void ResponseContentStart() { }

Expand Down

0 comments on commit 809b82e

Please sign in to comment.