Skip to content

Update the http.status_code on root-level aspnet.request spans after TransferRequest calls#2419

Merged
zacharycmontoya merged 12 commits into
masterfrom
zach/fix/aspnet-transferrequest-incorrectstatuscode
Feb 16, 2022
Merged

Update the http.status_code on root-level aspnet.request spans after TransferRequest calls#2419
zacharycmontoya merged 12 commits into
masterfrom
zach/fix/aspnet-transferrequest-incorrectstatuscode

Conversation

@zacharycmontoya

@zacharycmontoya zacharycmontoya commented Feb 9, 2022

Copy link
Copy Markdown
Contributor

Issue

HTTP Status Code Tag incorrect on root span

The issue occurs when the ASP.NET application calls System.Web.HttpServerUtility.TransferRequest. When this happens, the end-user of the site does not see any redirects, but internally IIS initiates a second request through the Integrated pipeline. This means there are two aspnet.request spans: one for the initial request, and one for the transferred request. While the parent relationship is correct, the root span is assigned a http.status_code tag of 200, whereas the inner span has the correct code (what the end-user sees in the HTTP response).

MVC scope not closed on error

There is also a second issue that was discovered while testing this fix: when there is an error in the processing of an MVC action, the AspNetMvc integration returns from the System.Web.Mvc.Async.AsyncControllerActionInvoker.EndInvokeAction method with Tracer.ActiveScope still returning the MVC span. This leads to new spans becoming children of the MVC span up until the ASP.NET pipeline signals the end of the request and we close the MVC span.

Fix

HTTP Status Code Tag incorrect on root span

The order of the HttpModule callbacks for the two requests (initial and transferred) is as follows:

- initial.BeginRequest
- transferred.BeginRequest
- transferred.EndRequest
- initial.EndRequest

The solution for the http.status_code tag is to modify the EndRequest callback to only set http-related tags once. When transferred.EndRequest is handled, we take the correct HTTP status code and apply it to both its span and the root span. Then, when initial.EndRequest is called, we see that the HTTP status code tag has already been set so we don't update them.

This commit shows the snapshot changes from applying the fix: b122aaf

Note: This solution seemed like the best solution because the HttpContext is not shared between the two requests, so the only way to share information between the two requests is with existing objects or with AsyncLocal storage.

MVC scope not closed on error

The solution for the MVC scope issue is to reset the active scope to its parent before leaving the AspNetMvc integration. While this could be done several ways, my approach is to overwrite the FinishOnClose bool and set it to false so we can close the Scope before exiting the method. The span will remain unfinished and will be finished when the request ends and we set the correct HTTP tags.

This commit shows the snapshot changes from applying the fix, which makes the second aspnet.request span a child of the first aspnet.request span, NOT the first aspnet-mvc.request span: ecf88d8

Testing

Tests are added to ensure that the root-span's http.status_code tag matches the HTTP response in the following scenarios:

  • AspNetMvc4
  • AspNetMvc5
  • WebApi2 (ASP.NET only, not OWIN)

@zacharycmontoya zacharycmontoya added the area:automatic-instrumentation Automatic instrumentation managed C# code (Datadog.Trace.ClrProfiler.Managed) label Feb 9, 2022
@zacharycmontoya zacharycmontoya self-assigned this Feb 9, 2022
@zacharycmontoya
zacharycmontoya requested a review from a team as a code owner February 9, 2022 23:48
@andrewlock

This comment has been minimized.

@pierotibou pierotibou left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM but I bugged so much on the review that I think I should admit that an approval would be a complete fake :)

AddHeaderTagsFromHttpResponse(app.Context, scope);

scope.Span.SetHttpStatusCode(app.Context.Response.StatusCode, isServer: true, Tracer.Instance.Settings);
// HttpServerUtility.TransferRequest presents an issue: The IIS request pipeline is run a second time

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the great comment

@andrewlock andrewlock left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice work 🎉

Comment thread tracer/src/Datadog.Trace/Scope.cs Outdated
Comment on lines +36 to +40
internal bool FinishOnClose
{
set => _finishOnClose = value;
}

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: setter-only properties feel weird 😂 An alternative suggestion, add a Dispose(bool finishOnClose) overload that does the same thing as

scope.FinishOnClose = false;
scope.Dispose();

@zacharycmontoya zacharycmontoya Feb 16, 2022

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah this does feel weird. The new dispose overload makes sense, but that opens us up to having Dispose() vs Dispose(bool finishOnClose) and likely Close() vs Close(bool finishOnClose). Instead of a set-only property, I'm thinking I'll just create a void method instead, possibly named SetFinishOnClose(bool finishOnClose). Does that sound good to you?

// Set span kind of span to server to pass through server span filtering
scope.Span.SetTag(Tags.SpanKind, SpanKinds.Server);

await base.HandleAsync(context, cancellationToken);

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

out of interest, why are we no longer calling this? 🤔 (Maybe just not necessary, can't remember why it was there)

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The ExceptionHandler class allows you to override either Handle or HandleAsync. Since I wanted to invoke TransferRequest and it's synchronous, I decided to switch to overriding Handle. As a result, it didn't make any sense to call base.HandleAsync anymore

@andrewlock

Copy link
Copy Markdown
Member

Benchmarks Report 🐌

Benchmarks for #2419 compared to master:

  • 3 benchmarks are slower, with geometric mean 1.140
  • All benchmarks have the same allocations

The following thresholds were used for comparing the benchmark speeds:

  • Mann–Whitney U test with statistical test for significance of 5%
  • Only results indicating a difference greater than 10% and 0.3 ns are considered.

Allocation changes below 0.5% are ignored.

Benchmark details

Benchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master WriteAndFlushEnrichedTraces net472 839μs 4.17μs 17.7μs 0 0 0 3.16 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 648μs 3.57μs 20.8μs 0 0 0 2.57 KB
#2419 WriteAndFlushEnrichedTraces net472 882μs 3.85μs 15.4μs 0 0 0 3.16 KB
#2419 WriteAndFlushEnrichedTraces netcoreapp3.1 673μs 2.25μs 8.1μs 0 0 0 2.57 KB
Benchmarks.Trace.AspNetCoreBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #2419

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.AspNetCoreBenchmark.SendRequest‑netcoreapp3.1 1.143 293,924.47 335,811.34

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendRequest net472 0ns 0ns 0ns 0 0 0 0 b
master SendRequest netcoreapp3.1 294μs 1.53μs 7.94μs 0.151 0 0 19.71 KB
#2419 SendRequest net472 0ns 0ns 0ns 0 0 0 0 b
#2419 SendRequest netcoreapp3.1 338μs 1.75μs 8.03μs 0.165 0 0 19.71 KB
Benchmarks.Trace.DbCommandBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteNonQuery net472 1.68μs 8.06ns 33.2ns 0.0924 0.000855 0 586 B
master ExecuteNonQuery netcoreapp3.1 1.59μs 8.88ns 56.8ns 0.00897 0 0 624 B
#2419 ExecuteNonQuery net472 1.75μs 9.4ns 50.6ns 0.0925 0.000865 0 586 B
#2419 ExecuteNonQuery netcoreapp3.1 1.57μs 8.81ns 57.1ns 0.00856 0 0 624 B
Benchmarks.Trace.ElasticsearchBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #2419

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.ElasticsearchBenchmark.CallElasticsearchAsync‑net472 1.154 2,684.17 3,097.42 several?

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master CallElasticsearch net472 2.47μs 11.4ns 42.5ns 0.126 0 0 794 B
master CallElasticsearch netcoreapp3.1 1.68μs 8.03ns 34.1ns 0.0108 0 0 784 B
master CallElasticsearchAsync net472 2.7μs 14.2ns 68ns 0.148 0.00131 0 931 B
master CallElasticsearchAsync netcoreapp3.1 1.84μs 8.21ns 31.8ns 0.0126 0 0 904 B
#2419 CallElasticsearch net472 2.62μs 13.9ns 73.7ns 0.126 0 0 794 B
#2419 CallElasticsearch netcoreapp3.1 1.72μs 7ns 27.1ns 0.0104 0 0 784 B
#2419 CallElasticsearchAsync net472 3.09μs 21.7ns 213ns 0.146 0 0 931 B
#2419 CallElasticsearchAsync netcoreapp3.1 1.9μs 9.46ns 40.1ns 0.0129 0 0 904 B
Benchmarks.Trace.GraphQLBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteAsync net472 2.99μs 11.8ns 44.2ns 0.167 0.00151 0 1.05 KB
master ExecuteAsync netcoreapp3.1 1.94μs 8.61ns 39.4ns 0.0144 0 0 1.02 KB
#2419 ExecuteAsync net472 3.13μs 12.8ns 49.5ns 0.166 0.00155 0 1.05 KB
#2419 ExecuteAsync netcoreapp3.1 2.11μs 10.6ns 48.6ns 0.0147 0 0 1.02 KB
Benchmarks.Trace.HttpClientBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendAsync net472 6.83μs 35.1ns 164ns 0.365 0 0 2.3 KB
master SendAsync netcoreapp3.1 4.69μs 9.78ns 37.9ns 0.0304 0 0 2.2 KB
#2419 SendAsync net472 7.47μs 43.2ns 351ns 0.36 0 0 2.3 KB
#2419 SendAsync netcoreapp3.1 4.74μs 17.9ns 69.4ns 0.0315 0 0 2.2 KB
Benchmarks.Trace.ILoggerBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net472 3.34μs 18.6ns 122ns 0.225 0 0 1.44 KB
master EnrichedLog netcoreapp3.1 3.05μs 17.1ns 118ns 0.0204 0 0 1.52 KB
#2419 EnrichedLog net472 3.41μs 19.5ns 149ns 0.224 0 0 1.44 KB
#2419 EnrichedLog netcoreapp3.1 3.26μs 18.7ns 146ns 0.0204 0 0 1.52 KB
Benchmarks.Trace.Log4netBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net472 292μs 1.62μs 10.4μs 0.416 0.139 0 4.31 KB
master EnrichedLog netcoreapp3.1 225μs 936ns 3.5μs 0 0 0 4.19 KB
#2419 EnrichedLog net472 298μs 1.08μs 3.9μs 0.441 0.147 0 4.31 KB
#2419 EnrichedLog netcoreapp3.1 237μs 792ns 2.86μs 0 0 0 4.19 KB
Benchmarks.Trace.NLogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net472 7.11μs 29.5ns 114ns 0.504 0 0 3.21 KB
master EnrichedLog netcoreapp3.1 6.27μs 22.8ns 88.3ns 0.0489 0 0 3.58 KB
#2419 EnrichedLog net472 7.38μs 34.5ns 129ns 0.501 0 0 3.21 KB
#2419 EnrichedLog netcoreapp3.1 6.41μs 25.4ns 98.5ns 0.0501 0 0 3.58 KB
Benchmarks.Trace.RedisBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #2419

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.RedisBenchmark.SendReceive‑netcoreapp3.1 1.124 2,018.46 2,268.21

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendReceive net472 2.24μs 10.7ns 42.6ns 0.159 0.00109 0 1 KB
master SendReceive netcoreapp3.1 2.03μs 11.3ns 69.7ns 0.0137 0 0 1 KB
#2419 SendReceive net472 2.27μs 9.35ns 35ns 0.159 0.00112 0 1 KB
#2419 SendReceive netcoreapp3.1 2.29μs 12.2ns 81ns 0.0145 0 0 1 KB
Benchmarks.Trace.SerilogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net472 5.75μs 24.4ns 100ns 0.288 0 0 1.85 KB
master EnrichedLog netcoreapp3.1 4.92μs 15ns 58.3ns 0.0191 0 0 1.47 KB
#2419 EnrichedLog net472 5.95μs 27.2ns 102ns 0.29 0 0 1.85 KB
#2419 EnrichedLog netcoreapp3.1 5.22μs 11.5ns 41.3ns 0.0207 0 0 1.47 KB
Benchmarks.Trace.SpanBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net472 908ns 2.57ns 9.96ns 0.0705 0 0 449 B
master StartFinishSpan netcoreapp3.1 869ns 4.62ns 25.3ns 0.00598 0 0 448 B
master StartFinishScope net472 1.06μs 5.87ns 49.8ns 0.083 0 0 530 B
master StartFinishScope netcoreapp3.1 1.01μs 4.03ns 15.1ns 0.00767 0 0 568 B
#2419 StartFinishSpan net472 956ns 5.36ns 39.4ns 0.0706 0 0 449 B
#2419 StartFinishSpan netcoreapp3.1 930ns 3.29ns 12.3ns 0.00634 0 0 448 B
#2419 StartFinishScope net472 1.1μs 6.21ns 48.9ns 0.0829 0 0 530 B
#2419 StartFinishScope netcoreapp3.1 1.08μs 4.28ns 16.6ns 0.00812 0 0 568 B

…line request for the same IISWorkerRequest object, store a new stack in an AsyncLocal field that maps RawUrl (doesn't change) ->StatusCode. This propagates up status codes to the original request, which would otherwise return a 200 even though on the wire the client observes a different HTTP status code.
… finishOnClose) method and add real unit tests
…" routes in Classic mode, where System.Web.HttpServerUtility.TransferRequest cannot be called
…apshots so the root-span metrics are placed in the correct order in the snapshots
@zacharycmontoya
zacharycmontoya force-pushed the zach/fix/aspnet-transferrequest-incorrectstatuscode branch from 4567478 to a40ea50 Compare February 16, 2022 17:10
@andrewlock

Copy link
Copy Markdown
Member

Code Coverage Report 📊

✔️ Merging #2419 into master will not change line coverage
✔️ Merging #2419 into master will not change branch coverage
⛔ Merging #2419 into master will will increase complexity by 7

master #2419 Change
Lines 11485 / 15867 11490 / 15880
Lines % 72% 72% 0% ✔️
Branches 6156 / 9270 6164 / 9276
Branches % 66% 66% 0% ✔️
Complexity 10473 10480 7

View the full report for further details:

Datadog.Trace Breakdown ✔️

master #2419 Change
Lines % 72% 72% 0% ✔️
Branches % 66% 66% 0% ✔️
Complexity 10473 10480 7

The following classes have significant coverage changes.

File Line coverage change Branch coverage change Complexity change
Datadog.Trace.ClrProfiler.AutoInstrumentation.MongoDb.MongoDbIntegration -7% 0% ✔️ 0 ✔️
Datadog.Trace.Scope 10% ✔️ 67% ✔️ 1
Datadog.Trace.Agent.TracesTransportStrategy 15% ✔️ 0% ✔️ 0 ✔️
Datadog.Trace.Telemetry.JsonHttpClientTelemetryTransport 26% ✔️ 38% ✔️ 0 ✔️
Datadog.Trace.Agent.StreamFactories.TcpStreamFactory 90% ✔️ 0% ✔️ 0 ✔️

View the full reports for further details:

@zacharycmontoya
zacharycmontoya merged commit f93b5ba into master Feb 16, 2022
@zacharycmontoya
zacharycmontoya deleted the zach/fix/aspnet-transferrequest-incorrectstatuscode branch February 16, 2022 19:18
@github-actions github-actions Bot added this to the vNext milestone Feb 16, 2022
andrewlock pushed a commit that referenced this pull request Feb 21, 2022
…TransferRequest calls (#2419)

When HttpServerUtility.TransferRequest is called, this results in two separate IIS pipeline requests where the HttpContext.Response object for the initial (unused) request has a 200 status code and the HttpContext.Response object for the second (transferred) request has the correct status. The issue was that the root span would be marked with a http.status_code=200, which does not corrrespond to the actual status code. This overrides the http.status_code tag of the root span with the correct status code.
andrewlock pushed a commit that referenced this pull request Feb 21, 2022
…TransferRequest calls (#2419)

When HttpServerUtility.TransferRequest is called, this results in two separate IIS pipeline requests where the HttpContext.Response object for the initial (unused) request has a 200 status code and the HttpContext.Response object for the second (transferred) request has the correct status. The issue was that the root span would be marked with a http.status_code=200, which does not corrrespond to the actual status code. This overrides the http.status_code tag of the root span with the correct status code.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

area:automatic-instrumentation Automatic instrumentation managed C# code (Datadog.Trace.ClrProfiler.Managed)

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants