Skip to content

[ASM] Remove warnings and fix flake#3338

Merged
robertpi merged 4 commits into
masterfrom
robert/asm/framework-blocking-flake
Oct 12, 2022
Merged

[ASM] Remove warnings and fix flake#3338
robertpi merged 4 commits into
masterfrom
robert/asm/framework-blocking-flake

Conversation

@robertpi

@robertpi robertpi commented Oct 11, 2022

Copy link
Copy Markdown
Member

Summary of changes

We are seeing flake in the ASM blocking tests, where the status code and resource name disappeared from the span:

framework flake

Reason for change

Flake is bad.

Implementation details

Before this change we dispose systematically disposed a scope / span in the TracingHttpModule.OnBeginRequest in the case of an exception, the logic being we won't be able to retrieve it from the http context TracingHttpModule.OnEndRequest.

However, this is not always true, if the exception occurs late TracingHttpModule.OnBeginRequest, then the span will be in the http context and we'll attempt to update the TracingHttpModule.OnEndRequest. This creates a race between data being written to the span object and the span being written to the AgentWriter.

In the case where we blocked the request from the call to the WAF in TracingHttpModule.OnBeginRequest, we were also calling the WAF again in TracingHttpModule.OnEndRequest, which seems unnecessary.

@andrewlock

This comment has been minimized.

@robertpi
robertpi force-pushed the robert/asm/framework-blocking-flake branch from c045fb6 to aef887f Compare October 11, 2022 13:26
@robertpi robertpi changed the title Stop trying to write tags after span is closed [ASM] Remove warnings and fix flake Oct 11, 2022
if (!transport.Blocked)
{
LastChanceToWriteTags?.Invoke(this, new InstrumentationGatewayEventArgs(transport, relatedSpan));
}

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

In the end, I think this change is not necessary, though seems a fairly sensible protection against unnecessary calls to the WAF.

{
LogAddressIfDebugEnabled(eventData);
eventHandler?.Invoke(this, new InstrumentationGatewaySecurityEventArgs(eventData, transport, relatedSpan, eraseExistingAddress));
}

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

Same as above 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.

This skips the debug log too though, is that correct?

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

I would say yes, we only really want to know what the input data is if it's going to be analyzed by the waf.

@robertpi
robertpi marked this pull request as ready for review October 11, 2022 13:48
@robertpi
robertpi requested review from a team as code owners October 11, 2022 13:48
@andrewlock

This comment has been minimized.

Comment on lines +120 to +121
var ea = new InstrumentationGatewayBlockingEventArgs(context, scope, tracerSettings, doBeforeActualBlocking);
BlockingOpportunity?.Invoke(this, ea);

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.

This now creates the InstrumentationGatewayBlockingEventArgs object even if BlockingOpportunity is null, that looks worse for allocations to me? 🤔

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

Agree, fixed in 52d5dec

@andrewlock

This comment has been minimized.

@andrewlock

Copy link
Copy Markdown
Member

Benchmarks Report 🐌

Benchmarks for #3338 compared to master:

  • All benchmarks have the same speed
  • 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 790μs 502ns 1.94μs 0.396 0 0 3.22 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 525μs 125ns 484ns 0 0 0 2.63 KB
#3338 WriteAndFlushEnrichedTraces net472 788μs 636ns 2.46μs 0.393 0 0 3.22 KB
#3338 WriteAndFlushEnrichedTraces netcoreapp3.1 539μs 267ns 997ns 0 0 0 2.62 KB
Benchmarks.Trace.AppSecBodyBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master AllCycleSimpleBody net472 198ns 0.277ns 1.21ns 0.0727 0 0 457 B
master AllCycleSimpleBody netcoreapp3.1 256ns 0.189ns 0.706ns 0.00632 0 0 456 B
master AllCycleMoreComplexBody net472 208ns 0.116ns 0.436ns 0.0688 0 0 433 B
master AllCycleMoreComplexBody netcoreapp3.1 254ns 0.223ns 0.865ns 0.00598 0 0 432 B
master BodyExtractorSimpleBody net472 293ns 0.208ns 0.805ns 0.0573 0 0 361 B
master BodyExtractorSimpleBody netcoreapp3.1 230ns 0.0689ns 0.267ns 0.0037 0 0 272 B
master BodyExtractorMoreComplexBody net472 15.7μs 12.1ns 47ns 1.21 0.0156 0 7.62 KB
master BodyExtractorMoreComplexBody netcoreapp3.1 13.1μs 4.57ns 17.1ns 0.0912 0 0 6.75 KB
#3338 AllCycleSimpleBody net472 203ns 0.128ns 0.496ns 0.0726 0 0 457 B
#3338 AllCycleSimpleBody netcoreapp3.1 253ns 0.147ns 0.551ns 0.00622 0 0 456 B
#3338 AllCycleMoreComplexBody net472 194ns 0.0568ns 0.212ns 0.0688 0 0 433 B
#3338 AllCycleMoreComplexBody netcoreapp3.1 250ns 0.139ns 0.54ns 0.00586 0 0 432 B
#3338 BodyExtractorSimpleBody net472 271ns 0.325ns 1.26ns 0.0574 0 0 361 B
#3338 BodyExtractorSimpleBody netcoreapp3.1 235ns 0.117ns 0.438ns 0.00367 0 0 272 B
#3338 BodyExtractorMoreComplexBody net472 15.6μs 11.4ns 44.1ns 1.21 0.0156 0 7.62 KB
#3338 BodyExtractorMoreComplexBody netcoreapp3.1 13μs 3.62ns 14ns 0.0909 0 0 6.75 KB
Benchmarks.Trace.AspNetCoreBenchmark - Same speed ✔️ Same allocations ✔️

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 180μs 208ns 807ns 0.271 0 0 20.68 KB
#3338 SendRequest net472 0ns 0ns 0ns 0 0 0 0 b
#3338 SendRequest netcoreapp3.1 181μs 218ns 844ns 0.271 0 0 20.68 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.81μs 1.09ns 4.23ns 0.155 0.00091 0 979 B
master ExecuteNonQuery netcoreapp3.1 1.39μs 0.731ns 2.74ns 0.0132 0 0 968 B
#3338 ExecuteNonQuery net472 1.93μs 0.861ns 3.22ns 0.155 0.00097 0 979 B
#3338 ExecuteNonQuery netcoreapp3.1 1.5μs 0.514ns 1.92ns 0.0126 0 0 968 B
Benchmarks.Trace.ElasticsearchBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master CallElasticsearch net472 2.44μs 0.6ns 2.24ns 0.189 0 0 1.19 KB
master CallElasticsearch netcoreapp3.1 1.5μs 0.752ns 2.81ns 0.0151 0 0 1.13 KB
master CallElasticsearchAsync net472 2.75μs 3.57ns 13.8ns 0.21 0 0 1.32 KB
master CallElasticsearchAsync netcoreapp3.1 1.59μs 1.41ns 5.26ns 0.0166 0 0 1.25 KB
#3338 CallElasticsearch net472 2.53μs 1.01ns 3.78ns 0.188 0 0 1.19 KB
#3338 CallElasticsearch netcoreapp3.1 1.56μs 0.773ns 2.99ns 0.0155 0 0 1.13 KB
#3338 CallElasticsearchAsync net472 2.7μs 0.953ns 3.56ns 0.21 0 0 1.32 KB
#3338 CallElasticsearchAsync netcoreapp3.1 1.57μs 0.962ns 3.47ns 0.0165 0 0 1.25 KB
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.82μs 1.01ns 3.78ns 0.23 0 0 1.45 KB
master ExecuteAsync netcoreapp3.1 1.75μs 0.496ns 1.92ns 0.0185 0 0 1.38 KB
#3338 ExecuteAsync net472 2.76μs 1.87ns 7.23ns 0.23 0 0 1.45 KB
#3338 ExecuteAsync netcoreapp3.1 1.79μs 2.03ns 7.86ns 0.0189 0 0 1.38 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 5.92μs 1.57ns 5.87ns 0.444 0 0 2.8 KB
master SendAsync netcoreapp3.1 3.75μs 1.58ns 5.69ns 0.0357 0 0 2.63 KB
#3338 SendAsync net472 5.91μs 2.55ns 9.86ns 0.444 0 0 2.8 KB
#3338 SendAsync netcoreapp3.1 3.6μs 1.87ns 6.98ns 0.0361 0 0 2.63 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.26μs 2.1ns 7.87ns 0.298 0 0 1.88 KB
master EnrichedLog netcoreapp3.1 2.52μs 1.17ns 4.4ns 0.0267 0 0 1.91 KB
#3338 EnrichedLog net472 3.29μs 1.72ns 5.95ns 0.298 0 0 1.88 KB
#3338 EnrichedLog netcoreapp3.1 2.58μs 4.76ns 18.5ns 0.0254 0 0 1.91 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 153μs 156ns 604ns 0.694 0.231 0 4.72 KB
master EnrichedLog netcoreapp3.1 118μs 239ns 925ns 0.0591 0 0 4.55 KB
#3338 EnrichedLog net472 152μs 156ns 604ns 0.68 0.227 0 4.72 KB
#3338 EnrichedLog netcoreapp3.1 116μs 189ns 733ns 0.0579 0 0 4.55 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 5.77μs 1.99ns 7.45ns 0.58 0.00281 0 3.65 KB
master EnrichedLog netcoreapp3.1 4.72μs 2.21ns 7.95ns 0.0542 0 0 3.98 KB
#3338 EnrichedLog net472 5.89μs 2.67ns 10ns 0.579 0.00289 0 3.65 KB
#3338 EnrichedLog netcoreapp3.1 4.6μs 2.05ns 7.67ns 0.0531 0 0 3.98 KB
Benchmarks.Trace.RedisBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendReceive net472 2.29μs 2.45ns 9.49ns 0.223 0 0 1.4 KB
master SendReceive netcoreapp3.1 1.79μs 2.01ns 7.54ns 0.018 0 0 1.35 KB
#3338 SendReceive net472 2.36μs 2.45ns 9.16ns 0.222 0 0 1.4 KB
#3338 SendReceive netcoreapp3.1 1.78μs 0.869ns 3.25ns 0.0188 0 0 1.35 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.2μs 1.99ns 7.72ns 0.363 0 0 2.3 KB
master EnrichedLog netcoreapp3.1 4.3μs 2ns 7.74ns 0.0237 0 0 1.86 KB
#3338 EnrichedLog net472 5.05μs 2.36ns 8.51ns 0.363 0 0 2.3 KB
#3338 EnrichedLog netcoreapp3.1 4.46μs 1.48ns 5.74ns 0.0244 0 0 1.86 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 1.15μs 0.271ns 1.01ns 0.134 0 0 842 B
master StartFinishSpan netcoreapp3.1 942ns 0.418ns 1.62ns 0.0109 0 0 792 B
master StartFinishScope net472 1.39μs 0.6ns 2.24ns 0.147 0 0 923 B
master StartFinishScope netcoreapp3.1 1.06μs 0.717ns 2.78ns 0.0122 0 0 912 B
#3338 StartFinishSpan net472 1.13μs 0.58ns 2.24ns 0.134 0 0 842 B
#3338 StartFinishSpan netcoreapp3.1 976ns 0.86ns 3.33ns 0.0108 0 0 792 B
#3338 StartFinishScope net472 1.39μs 1.03ns 3.98ns 0.146 0 0 923 B
#3338 StartFinishScope netcoreapp3.1 1.02μs 0.294ns 1.1ns 0.0122 0 0 912 B
Benchmarks.Trace.TraceAnnotationsBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master RunOnMethodBegin net472 1.54μs 0.414ns 1.49ns 0.146 0 0 923 B
master RunOnMethodBegin netcoreapp3.1 1.17μs 0.474ns 1.71ns 0.0123 0 0 912 B
#3338 RunOnMethodBegin net472 1.49μs 0.509ns 1.97ns 0.146 0 0 923 B
#3338 RunOnMethodBegin netcoreapp3.1 1.18μs 0.644ns 2.49ns 0.0125 0 0 912 B

@andrewlock

Copy link
Copy Markdown
Member

Code Coverage Report 📊

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

master #3338 Change
Lines 19367 / 26705 19302 / 26721
Lines % 73% 72% 0% ✔️
Branches 11527 / 16615 11503 / 16629
Branches % 69% 69% 0% ✔️
Complexity 17944 17966 22

View the full report for further details:

Datadog.Trace Breakdown ✔️

master #3338 Change
Lines % 73% 72% 0% ✔️
Branches % 69% 69% 0% ✔️
Complexity 17944 17966 22

The following classes have significant coverage changes.

File Line coverage change Branch coverage change Complexity change
Datadog.Trace.Ci.GitInfo -17% -11% 0 ✔️
Datadog.Trace.AppSec.Waf.Context -3% ⚠️ -10% 0 ✔️
Datadog.Trace.AppSec.InstrumentationGateway 1% ✔️ 17% ✔️ 8

View the full reports for further details:

@robertpi
robertpi merged commit 9e31841 into master Oct 12, 2022
@robertpi
robertpi deleted the robert/asm/framework-blocking-flake branch October 12, 2022 04:45
@github-actions github-actions Bot added this to the vNext milestone Oct 12, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants