[release/5.0] Http telemetry changes backport by MihaZupan · Pull Request #41610 · dotnet/runtime

MihaZupan · 2020-08-31T17:26:35Z

Joint changes of 3 related PRs: #41527, #41022, #41590 (they depend on each other, therefore they are merged in the port)

Customer Impact

Http telemetry: Request Start/Stop events don't properly correlate, which makes the end-to-end tracing impossible to use.
#41022 fixed that issue by moving the relevant telemetry instrumentation into HttpClient & HttpMessageInvoker.

The PR also adds more events that can provide more fine-grained insight into the lifetime of requests -- result of end-to-end validation and comparison with other stack:

RequestHeadersStart/Stop
RequestContentStart/Stop
ResponseHeadersStart/Stop
ResponseContentStart/Stop

RequestAborted event and counter were renamed to RequestFailed to align with naming of other *Failed events and to reflect their real purpose -- i.e. RequestFailed includes also non-successful HTTP response status codes (not quite an abort of request).

The PR further merges several event patterns together into parameterized HTTP version to avoid duplication (motivated by end-to-end validation feedback), for example:
Http11ConnectionEstablished and Http20ConnectionEstablished are merged into ConnectionEstablished(version).

Testing

Added a significant amount of testing to ensure the proper events and counters are emitted as part of this change.
There are a lot of existing tests covering HttpClient behavior in CI.
End-to-end manual validation in PerfView and using in-proc EventListener.

Risk

Small - There is minimal impact on non-Telemetry code path, because the change just shifts around code in HttpClient, but the changes are mostly copy/paste indentation changes (scope changes like including code in try-catch block, etc.).
Telemetry code paths are brand new - added during 5.0 (end of June), not yet consumed by any customers (beyond potentially early experimentation)

* Change HandshakeStop SslProtocols parameter to enum * Parameterize Http11/Http20 events * Add dummy request to ensure Http2 settings are received

* 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>

ghost · 2020-08-31T17:26:38Z

Tagging subscribers to this area: @dotnet/ncl
See info in area-owners.md if you want to be subscribed.

MihaZupan · 2020-08-31T17:30:14Z

/azp run runtime-libraries outerloop

azure-pipelines · 2020-08-31T17:30:28Z

Azure Pipelines successfully started running 1 pipeline(s).

karelz · 2020-08-31T18:28:01Z

+ if (!_concurrentStreams.TryRequestCreditNoWait(1))
 {
- if (!_concurrentStreams.TryRequestCreditNoWait(1))
+ if (_pool.EnableMultipleHttp2Connections)


Was swapping these 2 if checks intentional?

Yes. We only want to log RequestLeftQueue if we actually have to wait, so we have to perform the TryRequestCreditNoWait check first.
We already did so in the EnableMultipleHttp2Connections == true, so swapping the order around avoided duplicating a check.

karelz · 2020-08-31T19:38:23Z

@ericstj this is the Telemetry change I talked about -- we're aiming to have it ready for merge in a few hours. Let us know if you approve. Thanks!

ericstj · 2020-08-31T19:41:14Z

Approved since this is a blocking bug in a 5.0 feature.

scalablecory · 2020-08-31T19:42:32Z

+ (byte)request.Version.Major,
+ (byte)request.Version.Minor,


Are we okay truncating these if user sets them to something crazy? Seems like something they'd want to see in diagnostics.

I assumed we throw for anything unknown, do we allow it?

Not really. We allow it and we just connect over what we have (depending on VersionPolicy).
Minor is not checked almost at all (except for 1.0 and chunked content ASAIK).

What was the motivation to change to byte here?

scalablecory · 2020-08-31T19:47:27Z

 return s.mustFlush || s.endStream;
 }, cancellationToken).ConfigureAwait(false);
+
+ if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.RequestHeadersStop();


Is it intended that you'll get a broken Stop without a Start when the switch is flipped?

MihaZupan · 2020-08-31T19:56:21Z

Outerloop CI Failures: #40798, #41606, #41531, #41530

ManickaP

Except for open questions LGTM.

scalablecory

lgtm, just the question about the version truncation

MihaZupan · 2020-08-31T17:26:35Z

Joint changes of 3 related PRs: #41527, #41022, #41590 (they depend on each other, therefore they are merged in the port)

Customer Impact

Http telemetry: Request Start/Stop events don't properly correlate, which makes the end-to-end tracing impossible to use.
#41022 fixed that issue by moving the relevant telemetry instrumentation into HttpClient & HttpMessageInvoker.

The PR also adds more events that can provide more fine-grained insight into the lifetime of requests -- result of end-to-end validation and comparison with other stack:

RequestHeadersStart/Stop
RequestContentStart/Stop
ResponseHeadersStart/Stop
ResponseContentStart/Stop

RequestAborted event and counter were renamed to RequestFailed to align with naming of other *Failed events and to reflect their real purpose -- i.e. RequestFailed includes also non-successful HTTP response status codes (not quite an abort of request).

The PR further merges several event patterns together into parameterized HTTP version to avoid duplication (motivated by end-to-end validation feedback), for example:
Http11ConnectionEstablished and Http20ConnectionEstablished are merged into ConnectionEstablished(version).

Testing

Added a significant amount of testing to ensure the proper events and counters are emitted as part of this change.
There are a lot of existing tests covering HttpClient behavior in CI.
End-to-end manual validation in PerfView and using in-proc EventListener.

Risk

Small - There is minimal impact on non-Telemetry code path, because the change just shifts around code in HttpClient, but the changes are mostly copy/paste indentation changes (scope changes like including code in try-catch block, etc.).
Telemetry code paths are brand new - added during 5.0 (end of June), not yet consumed by any customers (beyond potentially early experimentation)

* Change HandshakeStop SslProtocols parameter to enum * Parameterize Http11/Http20 events * Add dummy request to ensure Http2 settings are received

* 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>

ghost · 2020-08-31T17:26:38Z

Tagging subscribers to this area: @dotnet/ncl
See info in area-owners.md if you want to be subscribed.

MihaZupan · 2020-08-31T17:30:14Z

/azp run runtime-libraries outerloop

azure-pipelines · 2020-08-31T17:30:28Z

Azure Pipelines successfully started running 1 pipeline(s).

karelz · 2020-08-31T18:28:01Z

+ if (!_concurrentStreams.TryRequestCreditNoWait(1))
 {
- if (!_concurrentStreams.TryRequestCreditNoWait(1))
+ if (_pool.EnableMultipleHttp2Connections)


Was swapping these 2 if checks intentional?

Yes. We only want to log RequestLeftQueue if we actually have to wait, so we have to perform the TryRequestCreditNoWait check first.
We already did so in the EnableMultipleHttp2Connections == true, so swapping the order around avoided duplicating a check.

karelz · 2020-08-31T19:38:23Z

@ericstj this is the Telemetry change I talked about -- we're aiming to have it ready for merge in a few hours. Let us know if you approve. Thanks!

ericstj · 2020-08-31T19:41:14Z

Approved since this is a blocking bug in a 5.0 feature.

scalablecory · 2020-08-31T19:42:32Z

+ (byte)request.Version.Major,
+ (byte)request.Version.Minor,


Are we okay truncating these if user sets them to something crazy? Seems like something they'd want to see in diagnostics.

I assumed we throw for anything unknown, do we allow it?

Not really. We allow it and we just connect over what we have (depending on VersionPolicy).
Minor is not checked almost at all (except for 1.0 and chunked content ASAIK).

What was the motivation to change to byte here?

scalablecory · 2020-08-31T19:47:27Z

 return s.mustFlush || s.endStream;
 }, cancellationToken).ConfigureAwait(false);
+
+ if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.RequestHeadersStop();


Is it intended that you'll get a broken Stop without a Start when the switch is flipped?

MihaZupan · 2020-08-31T19:56:21Z

Outerloop CI Failures: #40798, #41606, #41531, #41530

ManickaP

Except for open questions LGTM.

scalablecory

lgtm, just the question about the version truncation

MihaZupan · 2020-08-31T17:26:35Z

Joint changes of 3 related PRs: #41527, #41022, #41590 (they depend on each other, therefore they are merged in the port)

Customer Impact

Http telemetry: Request Start/Stop events don't properly correlate, which makes the end-to-end tracing impossible to use.
#41022 fixed that issue by moving the relevant telemetry instrumentation into HttpClient & HttpMessageInvoker.

The PR also adds more events that can provide more fine-grained insight into the lifetime of requests -- result of end-to-end validation and comparison with other stack:

RequestHeadersStart/Stop
RequestContentStart/Stop
ResponseHeadersStart/Stop
ResponseContentStart/Stop

RequestAborted event and counter were renamed to RequestFailed to align with naming of other *Failed events and to reflect their real purpose -- i.e. RequestFailed includes also non-successful HTTP response status codes (not quite an abort of request).

The PR further merges several event patterns together into parameterized HTTP version to avoid duplication (motivated by end-to-end validation feedback), for example:
Http11ConnectionEstablished and Http20ConnectionEstablished are merged into ConnectionEstablished(version).

Testing

Added a significant amount of testing to ensure the proper events and counters are emitted as part of this change.
There are a lot of existing tests covering HttpClient behavior in CI.
End-to-end manual validation in PerfView and using in-proc EventListener.

Risk

Small - There is minimal impact on non-Telemetry code path, because the change just shifts around code in HttpClient, but the changes are mostly copy/paste indentation changes (scope changes like including code in try-catch block, etc.).
Telemetry code paths are brand new - added during 5.0 (end of June), not yet consumed by any customers (beyond potentially early experimentation)

* Change HandshakeStop SslProtocols parameter to enum * Parameterize Http11/Http20 events * Add dummy request to ensure Http2 settings are received

* 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>

ghost · 2020-08-31T17:26:38Z

Tagging subscribers to this area: @dotnet/ncl
See info in area-owners.md if you want to be subscribed.

MihaZupan · 2020-08-31T17:30:14Z

/azp run runtime-libraries outerloop

azure-pipelines · 2020-08-31T17:30:28Z

Azure Pipelines successfully started running 1 pipeline(s).

karelz · 2020-08-31T18:28:01Z

+ if (!_concurrentStreams.TryRequestCreditNoWait(1))
 {
- if (!_concurrentStreams.TryRequestCreditNoWait(1))
+ if (_pool.EnableMultipleHttp2Connections)


Was swapping these 2 if checks intentional?

Yes. We only want to log RequestLeftQueue if we actually have to wait, so we have to perform the TryRequestCreditNoWait check first.
We already did so in the EnableMultipleHttp2Connections == true, so swapping the order around avoided duplicating a check.

karelz · 2020-08-31T19:38:23Z

@ericstj this is the Telemetry change I talked about -- we're aiming to have it ready for merge in a few hours. Let us know if you approve. Thanks!

ericstj · 2020-08-31T19:41:14Z

Approved since this is a blocking bug in a 5.0 feature.

scalablecory · 2020-08-31T19:42:32Z

+ (byte)request.Version.Major,
+ (byte)request.Version.Minor,


Are we okay truncating these if user sets them to something crazy? Seems like something they'd want to see in diagnostics.

I assumed we throw for anything unknown, do we allow it?

Not really. We allow it and we just connect over what we have (depending on VersionPolicy).
Minor is not checked almost at all (except for 1.0 and chunked content ASAIK).

What was the motivation to change to byte here?

scalablecory · 2020-08-31T19:47:27Z

 return s.mustFlush || s.endStream;
 }, cancellationToken).ConfigureAwait(false);
+
+ if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.RequestHeadersStop();


Is it intended that you'll get a broken Stop without a Start when the switch is flipped?

MihaZupan · 2020-08-31T19:56:21Z

Outerloop CI Failures: #40798, #41606, #41531, #41530

ManickaP

Except for open questions LGTM.

scalablecory

lgtm, just the question about the version truncation

MihaZupan · 2020-08-31T17:26:35Z

Joint changes of 3 related PRs: #41527, #41022, #41590 (they depend on each other, therefore they are merged in the port)

Customer Impact

Http telemetry: Request Start/Stop events don't properly correlate, which makes the end-to-end tracing impossible to use.
#41022 fixed that issue by moving the relevant telemetry instrumentation into HttpClient & HttpMessageInvoker.

The PR also adds more events that can provide more fine-grained insight into the lifetime of requests -- result of end-to-end validation and comparison with other stack:

RequestHeadersStart/Stop
RequestContentStart/Stop
ResponseHeadersStart/Stop
ResponseContentStart/Stop

RequestAborted event and counter were renamed to RequestFailed to align with naming of other *Failed events and to reflect their real purpose -- i.e. RequestFailed includes also non-successful HTTP response status codes (not quite an abort of request).

The PR further merges several event patterns together into parameterized HTTP version to avoid duplication (motivated by end-to-end validation feedback), for example:
Http11ConnectionEstablished and Http20ConnectionEstablished are merged into ConnectionEstablished(version).

Testing

Added a significant amount of testing to ensure the proper events and counters are emitted as part of this change.
There are a lot of existing tests covering HttpClient behavior in CI.
End-to-end manual validation in PerfView and using in-proc EventListener.

Risk

Small - There is minimal impact on non-Telemetry code path, because the change just shifts around code in HttpClient, but the changes are mostly copy/paste indentation changes (scope changes like including code in try-catch block, etc.).
Telemetry code paths are brand new - added during 5.0 (end of June), not yet consumed by any customers (beyond potentially early experimentation)

* Change HandshakeStop SslProtocols parameter to enum * Parameterize Http11/Http20 events * Add dummy request to ensure Http2 settings are received

* 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>

ghost · 2020-08-31T17:26:38Z

Tagging subscribers to this area: @dotnet/ncl
See info in area-owners.md if you want to be subscribed.

MihaZupan · 2020-08-31T17:30:14Z

/azp run runtime-libraries outerloop

azure-pipelines · 2020-08-31T17:30:28Z

Azure Pipelines successfully started running 1 pipeline(s).

karelz · 2020-08-31T18:28:01Z

+ if (!_concurrentStreams.TryRequestCreditNoWait(1))
 {
- if (!_concurrentStreams.TryRequestCreditNoWait(1))
+ if (_pool.EnableMultipleHttp2Connections)


Was swapping these 2 if checks intentional?

Yes. We only want to log RequestLeftQueue if we actually have to wait, so we have to perform the TryRequestCreditNoWait check first.
We already did so in the EnableMultipleHttp2Connections == true, so swapping the order around avoided duplicating a check.

karelz · 2020-08-31T19:38:23Z

@ericstj this is the Telemetry change I talked about -- we're aiming to have it ready for merge in a few hours. Let us know if you approve. Thanks!

ericstj · 2020-08-31T19:41:14Z

Approved since this is a blocking bug in a 5.0 feature.

scalablecory · 2020-08-31T19:42:32Z

+ (byte)request.Version.Major,
+ (byte)request.Version.Minor,


Are we okay truncating these if user sets them to something crazy? Seems like something they'd want to see in diagnostics.

I assumed we throw for anything unknown, do we allow it?

Not really. We allow it and we just connect over what we have (depending on VersionPolicy).
Minor is not checked almost at all (except for 1.0 and chunked content ASAIK).

What was the motivation to change to byte here?

scalablecory · 2020-08-31T19:47:27Z

 return s.mustFlush || s.endStream;
 }, cancellationToken).ConfigureAwait(false);
+
+ if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.RequestHeadersStop();


Is it intended that you'll get a broken Stop without a Start when the switch is flipped?

MihaZupan · 2020-08-31T19:56:21Z

Outerloop CI Failures: #40798, #41606, #41531, #41530

ManickaP

Except for open questions LGTM.

scalablecory

lgtm, just the question about the version truncation

MihaZupan · 2020-08-31T17:26:35Z

Joint changes of 3 related PRs: #41527, #41022, #41590 (they depend on each other, therefore they are merged in the port)

Customer Impact

Http telemetry: Request Start/Stop events don't properly correlate, which makes the end-to-end tracing impossible to use.
#41022 fixed that issue by moving the relevant telemetry instrumentation into HttpClient & HttpMessageInvoker.

The PR also adds more events that can provide more fine-grained insight into the lifetime of requests -- result of end-to-end validation and comparison with other stack:

RequestHeadersStart/Stop
RequestContentStart/Stop
ResponseHeadersStart/Stop
ResponseContentStart/Stop

RequestAborted event and counter were renamed to RequestFailed to align with naming of other *Failed events and to reflect their real purpose -- i.e. RequestFailed includes also non-successful HTTP response status codes (not quite an abort of request).

The PR further merges several event patterns together into parameterized HTTP version to avoid duplication (motivated by end-to-end validation feedback), for example:
Http11ConnectionEstablished and Http20ConnectionEstablished are merged into ConnectionEstablished(version).

Testing

Added a significant amount of testing to ensure the proper events and counters are emitted as part of this change.
There are a lot of existing tests covering HttpClient behavior in CI.
End-to-end manual validation in PerfView and using in-proc EventListener.

Risk

Small - There is minimal impact on non-Telemetry code path, because the change just shifts around code in HttpClient, but the changes are mostly copy/paste indentation changes (scope changes like including code in try-catch block, etc.).
Telemetry code paths are brand new - added during 5.0 (end of June), not yet consumed by any customers (beyond potentially early experimentation)

* Change HandshakeStop SslProtocols parameter to enum * Parameterize Http11/Http20 events * Add dummy request to ensure Http2 settings are received

* 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>

ghost · 2020-08-31T17:26:38Z

Tagging subscribers to this area: @dotnet/ncl
See info in area-owners.md if you want to be subscribed.

MihaZupan · 2020-08-31T17:30:14Z

/azp run runtime-libraries outerloop

azure-pipelines · 2020-08-31T17:30:28Z

Azure Pipelines successfully started running 1 pipeline(s).

karelz · 2020-08-31T18:28:01Z

+ if (!_concurrentStreams.TryRequestCreditNoWait(1))
 {
- if (!_concurrentStreams.TryRequestCreditNoWait(1))
+ if (_pool.EnableMultipleHttp2Connections)


Was swapping these 2 if checks intentional?

Yes. We only want to log RequestLeftQueue if we actually have to wait, so we have to perform the TryRequestCreditNoWait check first.
We already did so in the EnableMultipleHttp2Connections == true, so swapping the order around avoided duplicating a check.

karelz · 2020-08-31T19:38:23Z

@ericstj this is the Telemetry change I talked about -- we're aiming to have it ready for merge in a few hours. Let us know if you approve. Thanks!

ericstj · 2020-08-31T19:41:14Z

Approved since this is a blocking bug in a 5.0 feature.

scalablecory · 2020-08-31T19:42:32Z

+ (byte)request.Version.Major,
+ (byte)request.Version.Minor,


Are we okay truncating these if user sets them to something crazy? Seems like something they'd want to see in diagnostics.

I assumed we throw for anything unknown, do we allow it?

Not really. We allow it and we just connect over what we have (depending on VersionPolicy).
Minor is not checked almost at all (except for 1.0 and chunked content ASAIK).

What was the motivation to change to byte here?

scalablecory · 2020-08-31T19:47:27Z

 return s.mustFlush || s.endStream;
 }, cancellationToken).ConfigureAwait(false);
+
+ if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.RequestHeadersStop();


Is it intended that you'll get a broken Stop without a Start when the switch is flipped?

MihaZupan · 2020-08-31T19:56:21Z

Outerloop CI Failures: #40798, #41606, #41531, #41530

ManickaP

Except for open questions LGTM.

scalablecory

lgtm, just the question about the version truncation

MihaZupan · 2020-08-31T17:26:35Z

Joint changes of 3 related PRs: #41527, #41022, #41590 (they depend on each other, therefore they are merged in the port)

Customer Impact

Http telemetry: Request Start/Stop events don't properly correlate, which makes the end-to-end tracing impossible to use.
#41022 fixed that issue by moving the relevant telemetry instrumentation into HttpClient & HttpMessageInvoker.

The PR also adds more events that can provide more fine-grained insight into the lifetime of requests -- result of end-to-end validation and comparison with other stack:

RequestHeadersStart/Stop
RequestContentStart/Stop
ResponseHeadersStart/Stop
ResponseContentStart/Stop

RequestAborted event and counter were renamed to RequestFailed to align with naming of other *Failed events and to reflect their real purpose -- i.e. RequestFailed includes also non-successful HTTP response status codes (not quite an abort of request).

The PR further merges several event patterns together into parameterized HTTP version to avoid duplication (motivated by end-to-end validation feedback), for example:
Http11ConnectionEstablished and Http20ConnectionEstablished are merged into ConnectionEstablished(version).

Testing

Added a significant amount of testing to ensure the proper events and counters are emitted as part of this change.
There are a lot of existing tests covering HttpClient behavior in CI.
End-to-end manual validation in PerfView and using in-proc EventListener.

Risk

Small - There is minimal impact on non-Telemetry code path, because the change just shifts around code in HttpClient, but the changes are mostly copy/paste indentation changes (scope changes like including code in try-catch block, etc.).
Telemetry code paths are brand new - added during 5.0 (end of June), not yet consumed by any customers (beyond potentially early experimentation)

* Change HandshakeStop SslProtocols parameter to enum * Parameterize Http11/Http20 events * Add dummy request to ensure Http2 settings are received

* 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>

ghost · 2020-08-31T17:26:38Z

Tagging subscribers to this area: @dotnet/ncl
See info in area-owners.md if you want to be subscribed.

MihaZupan · 2020-08-31T17:30:14Z

/azp run runtime-libraries outerloop

azure-pipelines · 2020-08-31T17:30:28Z

Azure Pipelines successfully started running 1 pipeline(s).

karelz · 2020-08-31T18:28:01Z

+ if (!_concurrentStreams.TryRequestCreditNoWait(1))
 {
- if (!_concurrentStreams.TryRequestCreditNoWait(1))
+ if (_pool.EnableMultipleHttp2Connections)


Was swapping these 2 if checks intentional?

Yes. We only want to log RequestLeftQueue if we actually have to wait, so we have to perform the TryRequestCreditNoWait check first.
We already did so in the EnableMultipleHttp2Connections == true, so swapping the order around avoided duplicating a check.

karelz · 2020-08-31T19:38:23Z

@ericstj this is the Telemetry change I talked about -- we're aiming to have it ready for merge in a few hours. Let us know if you approve. Thanks!

ericstj · 2020-08-31T19:41:14Z

Approved since this is a blocking bug in a 5.0 feature.

scalablecory · 2020-08-31T19:42:32Z

+ (byte)request.Version.Major,
+ (byte)request.Version.Minor,


Are we okay truncating these if user sets them to something crazy? Seems like something they'd want to see in diagnostics.

I assumed we throw for anything unknown, do we allow it?

Not really. We allow it and we just connect over what we have (depending on VersionPolicy).
Minor is not checked almost at all (except for 1.0 and chunked content ASAIK).

What was the motivation to change to byte here?

scalablecory · 2020-08-31T19:47:27Z

 return s.mustFlush || s.endStream;
 }, cancellationToken).ConfigureAwait(false);
+
+ if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.RequestHeadersStop();


Is it intended that you'll get a broken Stop without a Start when the switch is flipped?

MihaZupan · 2020-08-31T19:56:21Z

Outerloop CI Failures: #40798, #41606, #41531, #41530

ManickaP

Except for open questions LGTM.

scalablecory

lgtm, just the question about the version truncation

MihaZupan · 2020-08-31T17:26:35Z

Joint changes of 3 related PRs: #41527, #41022, #41590 (they depend on each other, therefore they are merged in the port)

Customer Impact

Http telemetry: Request Start/Stop events don't properly correlate, which makes the end-to-end tracing impossible to use.
#41022 fixed that issue by moving the relevant telemetry instrumentation into HttpClient & HttpMessageInvoker.

The PR also adds more events that can provide more fine-grained insight into the lifetime of requests -- result of end-to-end validation and comparison with other stack:

RequestHeadersStart/Stop
RequestContentStart/Stop
ResponseHeadersStart/Stop
ResponseContentStart/Stop

RequestAborted event and counter were renamed to RequestFailed to align with naming of other *Failed events and to reflect their real purpose -- i.e. RequestFailed includes also non-successful HTTP response status codes (not quite an abort of request).

The PR further merges several event patterns together into parameterized HTTP version to avoid duplication (motivated by end-to-end validation feedback), for example:
Http11ConnectionEstablished and Http20ConnectionEstablished are merged into ConnectionEstablished(version).

Testing

Added a significant amount of testing to ensure the proper events and counters are emitted as part of this change.
There are a lot of existing tests covering HttpClient behavior in CI.
End-to-end manual validation in PerfView and using in-proc EventListener.

Risk

Small - There is minimal impact on non-Telemetry code path, because the change just shifts around code in HttpClient, but the changes are mostly copy/paste indentation changes (scope changes like including code in try-catch block, etc.).
Telemetry code paths are brand new - added during 5.0 (end of June), not yet consumed by any customers (beyond potentially early experimentation)

* Change HandshakeStop SslProtocols parameter to enum * Parameterize Http11/Http20 events * Add dummy request to ensure Http2 settings are received

* 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>

ghost · 2020-08-31T17:26:38Z

Tagging subscribers to this area: @dotnet/ncl
See info in area-owners.md if you want to be subscribed.

MihaZupan · 2020-08-31T17:30:14Z

/azp run runtime-libraries outerloop

azure-pipelines · 2020-08-31T17:30:28Z

Azure Pipelines successfully started running 1 pipeline(s).

karelz · 2020-08-31T18:28:01Z

+ if (!_concurrentStreams.TryRequestCreditNoWait(1))
 {
- if (!_concurrentStreams.TryRequestCreditNoWait(1))
+ if (_pool.EnableMultipleHttp2Connections)


Was swapping these 2 if checks intentional?

Yes. We only want to log RequestLeftQueue if we actually have to wait, so we have to perform the TryRequestCreditNoWait check first.
We already did so in the EnableMultipleHttp2Connections == true, so swapping the order around avoided duplicating a check.

karelz · 2020-08-31T19:38:23Z

@ericstj this is the Telemetry change I talked about -- we're aiming to have it ready for merge in a few hours. Let us know if you approve. Thanks!

ericstj · 2020-08-31T19:41:14Z

Approved since this is a blocking bug in a 5.0 feature.

scalablecory · 2020-08-31T19:42:32Z

+ (byte)request.Version.Major,
+ (byte)request.Version.Minor,


Are we okay truncating these if user sets them to something crazy? Seems like something they'd want to see in diagnostics.

I assumed we throw for anything unknown, do we allow it?

Not really. We allow it and we just connect over what we have (depending on VersionPolicy).
Minor is not checked almost at all (except for 1.0 and chunked content ASAIK).

What was the motivation to change to byte here?

scalablecory · 2020-08-31T19:47:27Z

 return s.mustFlush || s.endStream;
 }, cancellationToken).ConfigureAwait(false);
+
+ if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.RequestHeadersStop();


Is it intended that you'll get a broken Stop without a Start when the switch is flipped?

MihaZupan · 2020-08-31T19:56:21Z

Outerloop CI Failures: #40798, #41606, #41531, #41530

ManickaP

Except for open questions LGTM.

scalablecory

lgtm, just the question about the version truncation

MihaZupan · 2020-08-31T17:26:35Z

Joint changes of 3 related PRs: #41527, #41022, #41590 (they depend on each other, therefore they are merged in the port)

Customer Impact

Http telemetry: Request Start/Stop events don't properly correlate, which makes the end-to-end tracing impossible to use.
#41022 fixed that issue by moving the relevant telemetry instrumentation into HttpClient & HttpMessageInvoker.

The PR also adds more events that can provide more fine-grained insight into the lifetime of requests -- result of end-to-end validation and comparison with other stack:

RequestHeadersStart/Stop
RequestContentStart/Stop
ResponseHeadersStart/Stop
ResponseContentStart/Stop

RequestAborted event and counter were renamed to RequestFailed to align with naming of other *Failed events and to reflect their real purpose -- i.e. RequestFailed includes also non-successful HTTP response status codes (not quite an abort of request).

The PR further merges several event patterns together into parameterized HTTP version to avoid duplication (motivated by end-to-end validation feedback), for example:
Http11ConnectionEstablished and Http20ConnectionEstablished are merged into ConnectionEstablished(version).

Testing

Added a significant amount of testing to ensure the proper events and counters are emitted as part of this change.
There are a lot of existing tests covering HttpClient behavior in CI.
End-to-end manual validation in PerfView and using in-proc EventListener.

Risk

Small - There is minimal impact on non-Telemetry code path, because the change just shifts around code in HttpClient, but the changes are mostly copy/paste indentation changes (scope changes like including code in try-catch block, etc.).
Telemetry code paths are brand new - added during 5.0 (end of June), not yet consumed by any customers (beyond potentially early experimentation)

* Change HandshakeStop SslProtocols parameter to enum * Parameterize Http11/Http20 events * Add dummy request to ensure Http2 settings are received

* 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>

ghost · 2020-08-31T17:26:38Z

Tagging subscribers to this area: @dotnet/ncl
See info in area-owners.md if you want to be subscribed.

MihaZupan · 2020-08-31T17:30:14Z

/azp run runtime-libraries outerloop

azure-pipelines · 2020-08-31T17:30:28Z

Azure Pipelines successfully started running 1 pipeline(s).

karelz · 2020-08-31T18:28:01Z

+ if (!_concurrentStreams.TryRequestCreditNoWait(1))
 {
- if (!_concurrentStreams.TryRequestCreditNoWait(1))
+ if (_pool.EnableMultipleHttp2Connections)


Was swapping these 2 if checks intentional?

Yes. We only want to log RequestLeftQueue if we actually have to wait, so we have to perform the TryRequestCreditNoWait check first.
We already did so in the EnableMultipleHttp2Connections == true, so swapping the order around avoided duplicating a check.

karelz · 2020-08-31T19:38:23Z

@ericstj this is the Telemetry change I talked about -- we're aiming to have it ready for merge in a few hours. Let us know if you approve. Thanks!

ericstj · 2020-08-31T19:41:14Z

Approved since this is a blocking bug in a 5.0 feature.

scalablecory · 2020-08-31T19:42:32Z

+ (byte)request.Version.Major,
+ (byte)request.Version.Minor,


Are we okay truncating these if user sets them to something crazy? Seems like something they'd want to see in diagnostics.

I assumed we throw for anything unknown, do we allow it?

Not really. We allow it and we just connect over what we have (depending on VersionPolicy).
Minor is not checked almost at all (except for 1.0 and chunked content ASAIK).

What was the motivation to change to byte here?

scalablecory · 2020-08-31T19:47:27Z

 return s.mustFlush || s.endStream;
 }, cancellationToken).ConfigureAwait(false);
+
+ if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.RequestHeadersStop();


Is it intended that you'll get a broken Stop without a Start when the switch is flipped?

MihaZupan · 2020-08-31T19:56:21Z

Outerloop CI Failures: #40798, #41606, #41531, #41530

ManickaP

Except for open questions LGTM.

scalablecory

lgtm, just the question about the version truncation

MihaZupanand others added 3 commits August 31, 2020 18:49

System.Net Telemetry style changes (dotnet#41527)
41ffe5d
* Change HandshakeStop SslProtocols parameter to enum * Parameterize Http11/Http20 events * Add dummy request to ensure Http2 settings are received

Add Request/Response Headers/Content Start/Stop events (dotnet#41590)
8c3e421

MihaZupan added the area-System.Net.Http label Aug 31, 2020

MihaZupan added this to the 5.0.0 milestone Aug 31, 2020

MihaZupan requested review from a team, ManickaP, alnikola, karelz and scalablecory August 31, 2020 17:26

karelz approved these changes Aug 31, 2020
View reviewed changes

karelz reviewed Aug 31, 2020
View reviewed changes

Comment threadsrc/libraries/System.Net.Http/src/System/Net/Http/HttpRequestMessage.cs

scalablecory reviewed Aug 31, 2020
View reviewed changes

Comment threadsrc/libraries/System.Net.Http/src/System/Net/Http/HttpMessageInvoker.cs

scalablecory reviewed Aug 31, 2020
View reviewed changes

ManickaP approved these changes Aug 31, 2020
View reviewed changes

scalablecory approved these changes Aug 31, 2020
View reviewed changes

MihaZupan merged commit 6b1b038 into dotnet:release/5.0Aug 31, 2020

This was referenced Sep 1, 2020
ActivityId missing in a newly added HttpTelemetry Stop events. #40776
Closed
Test failure: System.Net.Http.Functional.Tests.TelemetryTest_Http11.EventSource_ConnectionPoolAtMaxConnections_LogsRequestLeftQueue #40926
Closed

ghost locked as resolved and limited conversation to collaborators Dec 7, 2020