Add missing header tags in unhandled exception handler in ASP.NET Core by andrewlock · Pull Request #2460 · DataDog/dd-trace-dotnet

andrewlock · 2022-02-17T14:14:15Z

Summary of changes

Ensure we add response header tags (if required) when an exception occurs in the middleware pipeline

Reason for change

Discovered while investigating #2458. We noticed that we were not calling SetHeaderTags() to record response headers when an unhandled exception occurs in the middleware/mvc pipeline.

/cc @zacharycmontoya as you implemented this originally I believe - is there any reason you're aware of that we shouldn't be doing this?

Implementation details

Set the response headers if we need to.

Test coverage

Updated the snapshots to include the missing response headers for the "erroring" endpoints.

Note that the snapshots show we're not recording the correlation id header (for example) in these error cases. I'm not sure why, but it is likely due to the way the middleware pipeline works (i.e. the header is not being added!)

@DataDog/apm-dotnet

zacharycmontoya · 2022-02-17T14:40:23Z

/cc @zacharycmontoya as you implemented this originally I believe - is there any reason you're aware of that we shouldn't be doing this?

I can't think of a reason that we shouldn't do this. It was probably (incorrectly) assumed that the end request handlers would handle this case

andrewlock · 2022-02-17T14:41:00Z

I can't think of a reason that we shouldn't do this. It was probably assumed that the end request handlers would handle this case

Great, that's what we thought, thanks!

pierotibou · 2022-02-18T09:58:20Z


                // Generic unhandled exceptions are converted to 500 errors by Kestrel
                span.SetHttpStatusCode(statusCode: statusCode, isServer: true, tracer.Settings);
+                span.SetHeaderTags(new HeadersCollectionAdapter(unhandledStruct.HttpContext.Response.Headers), tracer.Settings.HeaderTags, defaultTagPrefix: SpanContextPropagator.HttpResponseHeadersTagPrefix);


Not asking to change anything, more a philosophical question that I asked myself.
I wonder if we could find a way to make sure we ask ourselves the question "should I also set the header" when we set a httpstatuscode. I thought maybe adding a new method on Span doing both could be a way as people would see it and ask themselves the question. But I find it kinda ugly.
Anyway, if you think this comment is relevant and you find a more appropriate idea, it could be nice to reduce the risk of forgetting this in the future.

I don't think we can combine these, as we don't set header tags for client requests (e.g. HttpClient, AWS's SDK client etc). We only set them for "server" requests (aspnet, aspnetcore).

If we should be setting them on client http spans, then that's another question! 😄

We should be recording response headers when an exception is thrown too. Note that the snapshots show we're not recording the correlation id header (for example) in these error cases. I'm not sure why, but it is likely due to the way the middleware pipeline works

andrewlock · 2022-02-20T20:56:13Z

Benchmarks Report 🐌

Benchmarks for #2460 compared to master:

1 benchmarks are faster, with geometric mean 1.121
1 benchmarks are slower, with geometric mean 1.193
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	Allocated
master	`WriteAndFlushEnrichedTraces`	net472	885μs	3.08μs	11.9μs	3.16 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	732μs	4.19μs	38μs	2.57 KB
#2460	`WriteAndFlushEnrichedTraces`	net472	916μs	4.24μs	17μs	3.16 KB
#2460	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	713μs	3.37μs	13.5μs	2.57 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendRequest`	net472	0ns	0ns	0ns	0	0 b
master	`SendRequest`	netcoreapp3.1	336μs	907ns	3.51μs	0.17	19.71 KB
#2460	`SendRequest`	net472	0ns	0ns	0ns	0	0 b
#2460	`SendRequest`	netcoreapp3.1	353μs	1.72μs	7.5μs	0.171	19.71 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`ExecuteNonQuery`	net472	1.72μs	8.76ns	40.2ns	0.0928	0.000859	586 B
master	`ExecuteNonQuery`	netcoreapp3.1	1.58μs	8.61ns	48ns	0.00844	0	624 B
#2460	`ExecuteNonQuery`	net472	1.86μs	5.93ns	21.4ns	0.0926	0	586 B
#2460	`ExecuteNonQuery`	netcoreapp3.1	1.56μs	4.72ns	17.7ns	0.00851	0	624 B

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`CallElasticsearch`	net472	2.62μs	14ns	73.9ns	0.125	0	794 B
master	`CallElasticsearch`	netcoreapp3.1	1.84μs	10.6ns	89.9ns	0.0106	0	784 B
master	`CallElasticsearchAsync`	net472	3.08μs	14.8ns	57.2ns	0.147	0.00153	931 B
master	`CallElasticsearchAsync`	netcoreapp3.1	2μs	12ns	119ns	0.0123	0	904 B
#2460	`CallElasticsearch`	net472	2.67μs	12.3ns	47.7ns	0.126	0	794 B
#2460	`CallElasticsearch`	netcoreapp3.1	1.9μs	11.1ns	102ns	0.0106	0	784 B
#2460	`CallElasticsearchAsync`	net472	2.81μs	10.3ns	38.5ns	0.147	0	931 B
#2460	`CallElasticsearchAsync`	netcoreapp3.1	1.91μs	5.18ns	18.7ns	0.012	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	3.04μs	13.1ns	47.2ns	0.166	0	0	1.05 KB
master	`ExecuteAsync`	netcoreapp3.1	2.14μs	7.02ns	24.3ns	0.0136	0	0	1.02 KB
#2460	`ExecuteAsync`	net472	3.08μs	11.5ns	44.7ns	0.166	0.00304	0.00152	1.05 KB
#2460	`ExecuteAsync`	netcoreapp3.1	2.18μs	11.4ns	59ns	0.0139	0	0	1.02 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendAsync`	net472	7.23μs	31.3ns	121ns	0.363	2.3 KB
master	`SendAsync`	netcoreapp3.1	4.81μs	22.3ns	89.1ns	0.0318	2.2 KB
#2460	`SendAsync`	net472	7.63μs	38ns	170ns	0.362	2.3 KB
#2460	`SendAsync`	netcoreapp3.1	5.1μs	21.7ns	78.1ns	0.0315	2.2 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net472	3.32μs	15.4ns	57.7ns	0.224	1.44 KB
master	`EnrichedLog`	netcoreapp3.1	3.17μs	10.6ns	38.4ns	0.0206	1.52 KB
#2460	`EnrichedLog`	net472	3.65μs	20.9ns	157ns	0.225	1.44 KB
#2460	`EnrichedLog`	netcoreapp3.1	3.23μs	14.3ns	55.3ns	0.0203	1.52 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`EnrichedLog`	net472	297μs	1.08μs	4.05μs	0.439	0.146	4.31 KB
master	`EnrichedLog`	netcoreapp3.1	235μs	1.01μs	3.64μs	0	0	4.19 KB
#2460	`EnrichedLog`	net472	305μs	747ns	2.8μs	0.453	0.151	4.31 KB
#2460	`EnrichedLog`	netcoreapp3.1	244μs	1.14μs	4.43μs	0	0	4.19 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net472	7.72μs	44.8ns	373ns	0.5	3.21 KB
master	`EnrichedLog`	netcoreapp3.1	6.73μs	38.3ns	363ns	0.0492	3.58 KB
#2460	`EnrichedLog`	net472	8.16μs	53.3ns	527ns	0.503	3.21 KB
#2460	`EnrichedLog`	netcoreapp3.1	6.86μs	27.9ns	104ns	0.0474	3.58 KB

Benchmarks.Trace.RedisBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #2460

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.RedisBenchmark.SendReceive‑net472	1.193	2,317.71	2,763.91

Faster 🎉 in #2460

Benchmark	base/diff	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.RedisBenchmark.SendReceive‑netcoreapp3.1	1.121	2,360.93	2,105.43

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendReceive`	net472	2.32μs	9.1ns	32.8ns	0.159	1 KB
master	`SendReceive`	netcoreapp3.1	2.38μs	11.7ns	52.4ns	0.0139	1 KB
#2460	`SendReceive`	net472	2.77μs	9.73ns	36.4ns	0.159	1 KB
#2460	`SendReceive`	netcoreapp3.1	2.11μs	6.97ns	27ns	0.0136	1 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net472	6.26μs	32.4ns	155ns	0.289	1.85 KB
master	`EnrichedLog`	netcoreapp3.1	5.2μs	19.2ns	74.2ns	0.021	1.47 KB
#2460	`EnrichedLog`	net472	6.33μs	14.4ns	54ns	0.287	1.85 KB
#2460	`EnrichedLog`	netcoreapp3.1	5.31μs	25ns	96.7ns	0.0185	1.47 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`StartFinishSpan`	net472	920ns	4.37ns	16.9ns	0.0703	449 B
master	`StartFinishSpan`	netcoreapp3.1	892ns	2.5ns	9.67ns	0.00592	448 B
master	`StartFinishScope`	net472	1.09μs	2.92ns	10.9ns	0.0829	530 B
master	`StartFinishScope`	netcoreapp3.1	1.1μs	3.59ns	13.9ns	0.00772	568 B
#2460	`StartFinishSpan`	net472	977ns	5.64ns	47.2ns	0.0704	449 B
#2460	`StartFinishSpan`	netcoreapp3.1	923ns	3.64ns	13.6ns	0.00598	448 B
#2460	`StartFinishScope`	net472	1.12μs	3.07ns	11.5ns	0.083	530 B
#2460	`StartFinishScope`	netcoreapp3.1	1.08μs	3ns	11.2ns	0.00791	568 B

andrewlock · 2022-02-20T21:14:51Z

Code Coverage Report 📊

✔️ Merging #2460 into master will not change line coverage
✔️ Merging #2460 into master will not change branch coverage
✔️ Merging #2460 into master will not change complexity

	master	#2460	Change
Lines	`11610` / `15971`	`11578` / `15972`
Lines %	`73%`	`72%`	`0%` ✔️
Branches	`6232` / `9336`	`6219` / `9336`
Branches %	`67%`	`67%`	`0%` ✔️
Complexity	`10546`	`10546`	`0` ✔️

View the full report for further details:

Datadog.Trace Breakdown ✔️

	master	#2460	Change
Lines %	`73%`	`72%`	`0%` ✔️
Branches %	`67%`	`67%`	`0%` ✔️
Complexity	`10546`	`10546`	`0` ✔️

The following classes have significant coverage changes.

File	Line coverage change	Branch coverage change	Complexity change
Datadog.Trace.Ci.Agent.CIAgentWriter	`-10%` ⛔	`-21%` ⛔	`0` ✔️
Datadog.Trace.ClrProfiler.AutoInstrumentation.MongoDb.MongoDbIntegration	`-7%` ⛔	`0%` ✔️	`0` ✔️

View the full reports for further details:

andrewlock · 2022-02-21T14:20:30Z

Superseded by #2480

andrewlock added type:bug area:automatic-instrumentation Automatic instrumentation managed C# code (Datadog.Trace.ClrProfiler.Managed) labels Feb 17, 2022

andrewlock requested a review from a team as a code owner February 17, 2022 14:14

andrewlock mentioned this pull request Feb 17, 2022

Fix missing http.status_code tag on ASP.NET Core spans with errors #2458

Merged

This comment has been minimized.

Sign in to view

pierotibou approved these changes Feb 18, 2022

View reviewed changes

andrewlock force-pushed the andrew/add-missing-response-headers branch from 48e1957 to e337325 Compare February 20, 2022 19:57

This was referenced Feb 21, 2022

Backport fixes to 1.x #2479

Merged

Always set response header tags in ASP.NET Core #2480

Merged

andrewlock closed this Feb 21, 2022

andrewlock deleted the andrew/add-missing-response-headers branch March 14, 2022 14:32

Uh oh!

Conversation

andrewlock commented Feb 17, 2022

Summary of changes

Reason for change

Implementation details

Test coverage

Uh oh!

zacharycmontoya commented Feb 17, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

andrewlock commented Feb 17, 2022

Uh oh!

This comment has been minimized.

This comment has been minimized.

pierotibou Feb 18, 2022

Choose a reason for hiding this comment

Uh oh!

andrewlock Feb 18, 2022

Choose a reason for hiding this comment

Uh oh!

andrewlock commented Feb 20, 2022

Benchmarks Report 🐌

Benchmark details

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #2460

Faster 🎉 in #2460

Raw results

Raw results

Raw results

Uh oh!

andrewlock commented Feb 20, 2022

Code Coverage Report 📊

Datadog.Trace Breakdown ✔️

Uh oh!

andrewlock commented Feb 21, 2022

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

zacharycmontoya commented Feb 17, 2022 •

edited

Loading