Update the http.status_code on root-level aspnet.request spans after TransferRequest calls#2419
Conversation
This comment has been minimized.
This comment has been minimized.
pierotibou
left a comment
There was a problem hiding this comment.
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 |
There was a problem hiding this comment.
Thanks for the great comment
| internal bool FinishOnClose | ||
| { | ||
| set => _finishOnClose = value; | ||
| } | ||
|
|
There was a problem hiding this comment.
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();There was a problem hiding this comment.
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); |
There was a problem hiding this comment.
out of interest, why are we no longer calling this? 🤔 (Maybe just not necessary, can't remember why it was there)
There was a problem hiding this comment.
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
Benchmarks Report 🐌Benchmarks for #2419 compared to master:
The following thresholds were used for comparing the benchmark speeds:
Allocation changes below 0.5% are ignored. Benchmark detailsBenchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.AspNetCoreBenchmark - Slower
|
| 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?
| 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
| 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.
… scope is no longer the MVC span.
… 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
4567478 to
a40ea50
Compare
Code Coverage Report 📊✔️ Merging #2419 into master will not change line coverage
View the full report for further details: Datadog.Trace Breakdown ✔️
The following classes have significant coverage changes.
View the full reports for further details: |
…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.
…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.
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 twoaspnet.requestspans: one for the initial request, and one for the transferred request. While the parent relationship is correct, the root span is assigned ahttp.status_codetag 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.EndInvokeActionmethod withTracer.ActiveScopestill 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 (
initialandtransferred) is as follows:The solution for the
http.status_codetag is to modify theEndRequestcallback to only set http-related tags once. Whentransferred.EndRequestis handled, we take the correct HTTP status code and apply it to both its span and the root span. Then, wheninitial.EndRequestis called, we see that the HTTP status code tag has already been set so we don't update them.Note: This solution seemed like the best solution because the
HttpContextis not shared between the two requests, so the only way to share information between the two requests is with existing objects or withAsyncLocalstorage.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
FinishOnClosebool and set it tofalseso 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.Testing
Tests are added to ensure that the root-span's
http.status_codetag matches the HTTP response in the following scenarios: