[ASM] Context disposed related exceptions when calling the WAF #6529
+226
−25
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Execution-Time Benchmarks Report ⏱️Execution-time results for samples comparing the following branches/commits: Execution-time benchmarks measure the whole time it takes to execute a program. And are intended to measure the one-off costs. Cases where the execution time results for the PR are worse than latest master results are shown in red. The following thresholds were used for comparing the execution times:
Note that these results are based on a single point-in-time result for each branch. For full results, see the dashboard. Graphs show the p99 interval based on the mean and StdDev of the test run, as well as the mean value of the run (shown as a diamond below the graph). gantt
title Execution time (ms) FakeDbCommand (.NET Framework 4.6.2)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6529) - mean (69ms) : 66, 71
. : milestone, 69,
master - mean (69ms) : 66, 72
. : milestone, 69,
section CallTarget+Inlining+NGEN
This PR (6529) - mean (978ms) : 956, 1000
. : milestone, 978,
master - mean (975ms) : 950, 1001
. : milestone, 975,
gantt
title Execution time (ms) FakeDbCommand (.NET Core 3.1)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6529) - mean (107ms) : 104, 110
. : milestone, 107,
master - mean (108ms) : 105, 110
. : milestone, 108,
section CallTarget+Inlining+NGEN
This PR (6529) - mean (678ms) : 665, 692
. : milestone, 678,
master - mean (679ms) : 664, 694
. : milestone, 679,
gantt
title Execution time (ms) FakeDbCommand (.NET 6)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6529) - mean (91ms) : 89, 93
. : milestone, 91,
master - mean (91ms) : 90, 93
. : milestone, 91,
section CallTarget+Inlining+NGEN
This PR (6529) - mean (634ms) : 615, 653
. : milestone, 634,
master - mean (635ms) : 619, 651
. : milestone, 635,
gantt
title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6529) - mean (190ms) : 186, 195
. : milestone, 190,
master - mean (194ms) : 189, 198
. : milestone, 194,
section CallTarget+Inlining+NGEN
This PR (6529) - mean (1,088ms) : 1067, 1110
. : milestone, 1088,
master - mean (1,094ms) : 1067, 1122
. : milestone, 1094,
gantt
title Execution time (ms) HttpMessageHandler (.NET Core 3.1)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6529) - mean (275ms) : 271, 279
. : milestone, 275,
master - mean (277ms) : 273, 281
. : milestone, 277,
section CallTarget+Inlining+NGEN
This PR (6529) - mean (865ms) : 840, 890
. : milestone, 865,
master - mean (871ms) : 849, 892
. : milestone, 871,
gantt
title Execution time (ms) HttpMessageHandler (.NET 6)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6529) - mean (264ms) : 261, 266
. : milestone, 264,
master - mean (267ms) : 263, 271
. : milestone, 267,
section CallTarget+Inlining+NGEN
This PR (6529) - mean (849ms) : 817, 881
. : milestone, 849,
master - mean (855ms) : 820, 889
. : milestone, 855,
|
Datadog ReportBranch report: ✅ 0 Failed, 242821 Passed, 1967 Skipped, 18h 52m 53.63s Total Time |
Benchmarks Report for appsec 🐌Benchmarks for #6529 compared to master:
The following thresholds were used for comparing the benchmark speeds:
Allocation changes below 0.5% are ignored. Benchmark detailsBenchmarks.Trace.Asm.AppSecBodyBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.Asm.AppSecEncoderBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.Asm.AppSecWafBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.Iast.StringAspectsBenchmark - Same speed ✔️ More allocations
|
| Benchmark | Base Allocated | Diff Allocated | Change | Change % |
|---|---|---|---|---|
| Benchmarks.Trace.Iast.StringAspectsBenchmark.StringConcatBenchmark‑net472 | 59.07 KB | 59.46 KB | 392 B | 0.66% |
| Benchmark | Base Allocated | Diff Allocated | Change | Change % |
|---|---|---|---|---|
| Benchmarks.Trace.Iast.StringAspectsBenchmark.StringConcatAspectBenchmark‑netcoreapp3.1 | 255.27 KB | 253.58 KB | -1.69 KB | -0.66% |
| Benchmarks.Trace.Iast.StringAspectsBenchmark.StringConcatAspectBenchmark‑net6.0 | 264.02 KB | 255.85 KB | -8.18 KB | -3.10% |
Raw results
| Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
|---|---|---|---|---|---|---|---|---|---|
| master | StringConcatBenchmark |
net6.0 | 59.4μs | 518ns | 4.75μs | 0 | 0 | 0 | 43.44 KB |
| master | StringConcatBenchmark |
netcoreapp3.1 | 54μs | 236ns | 818ns | 0 | 0 | 0 | 42.64 KB |
| master | StringConcatBenchmark |
net472 | 38.5μs | 174ns | 651ns | 0 | 0 | 0 | 59.07 KB |
| master | StringConcatAspectBenchmark |
net6.0 | 308μs | 1.36μs | 5.11μs | 0 | 0 | 0 | 264.02 KB |
| master | StringConcatAspectBenchmark |
netcoreapp3.1 | 346μs | 1.71μs | 7.64μs | 0 | 0 | 0 | 255.27 KB |
| master | StringConcatAspectBenchmark |
net472 | 282μs | 5.75μs | 55.4μs | 0 | 0 | 0 | 278.53 KB |
| #6529 | StringConcatBenchmark |
net6.0 | 59.1μs | 739ns | 7.24μs | 0 | 0 | 0 | 43.44 KB |
| #6529 | StringConcatBenchmark |
netcoreapp3.1 | 54.6μs | 300ns | 1.72μs | 0 | 0 | 0 | 42.64 KB |
| #6529 | StringConcatBenchmark |
net472 | 37.7μs | 182ns | 706ns | 0 | 0 | 0 | 59.46 KB |
| #6529 | StringConcatAspectBenchmark |
net6.0 | 317μs | 1.77μs | 11.8μs | 0 | 0 | 0 | 255.85 KB |
| #6529 | StringConcatAspectBenchmark |
netcoreapp3.1 | 348μs | 1.81μs | 12μs | 0 | 0 | 0 | 253.58 KB |
| #6529 | StringConcatAspectBenchmark |
net472 | 299μs | 7.06μs | 69.6μs | 0 | 0 | 0 | 278.53 KB |
Benchmarks Report for tracer 🐌Benchmarks for #6529 compared to master:
The following thresholds were used for comparing the benchmark speeds:
Allocation changes below 0.5% are ignored. Benchmark detailsBenchmarks.Trace.ActivityBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.AspNetCoreBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.DbCommandBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.ElasticsearchBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.GraphQLBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.HttpClientBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.ILoggerBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.Log4netBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.NLogBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.RedisBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.SerilogBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.SpanBenchmark - Slower
|
| Benchmark | diff/base | Base Median (ns) | Diff Median (ns) | Modality |
|---|---|---|---|---|
| Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net6.0 | 1.168 | 395.56 | 461.95 | |
| Benchmarks.Trace.SpanBenchmark.StartFinishScope‑net472 | 1.126 | 816.48 | 918.99 |
| Benchmark | base/diff | Base Median (ns) | Diff Median (ns) | Modality |
|---|---|---|---|---|
| Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net472 | 1.117 | 712.20 | 637.82 |
Raw results
| Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
|---|---|---|---|---|---|---|---|---|---|
| master | StartFinishSpan |
net6.0 | 396ns | 0.259ns | 1ns | 0.00804 | 0 | 0 | 576 B |
| master | StartFinishSpan |
netcoreapp3.1 | 621ns | 1.21ns | 4.7ns | 0.00773 | 0 | 0 | 576 B |
| master | StartFinishSpan |
net472 | 712ns | 0.333ns | 1.29ns | 0.0916 | 0 | 0 | 578 B |
| master | StartFinishScope |
net6.0 | 466ns | 0.212ns | 0.766ns | 0.00978 | 0 | 0 | 696 B |
| master | StartFinishScope |
netcoreapp3.1 | 718ns | 2.25ns | 8.73ns | 0.0094 | 0 | 0 | 696 B |
| master | StartFinishScope |
net472 | 817ns | 0.954ns | 3.7ns | 0.104 | 0 | 0 | 658 B |
| #6529 | StartFinishSpan |
net6.0 | 462ns | 0.194ns | 0.726ns | 0.0081 | 0 | 0 | 576 B |
| #6529 | StartFinishSpan |
netcoreapp3.1 | 558ns | 0.551ns | 2.13ns | 0.00781 | 0 | 0 | 576 B |
| #6529 | StartFinishSpan |
net472 | 638ns | 0.582ns | 2.26ns | 0.0917 | 0 | 0 | 578 B |
| #6529 | StartFinishScope |
net6.0 | 476ns | 0.387ns | 1.5ns | 0.00974 | 0 | 0 | 696 B |
| #6529 | StartFinishScope |
netcoreapp3.1 | 750ns | 0.288ns | 1.12ns | 0.00935 | 0 | 0 | 696 B |
| #6529 | StartFinishScope |
net472 | 919ns | 0.337ns | 1.3ns | 0.104 | 0 | 0 | 658 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 |
net6.0 | 609ns | 0.354ns | 1.37ns | 0.00974 | 0 | 0 | 696 B |
| master | RunOnMethodBegin |
netcoreapp3.1 | 970ns | 0.624ns | 2.34ns | 0.00962 | 0 | 0 | 696 B |
| master | RunOnMethodBegin |
net472 | 1.12μs | 0.636ns | 2.46ns | 0.104 | 0 | 0 | 658 B |
| #6529 | RunOnMethodBegin |
net6.0 | 672ns | 0.192ns | 0.742ns | 0.00971 | 0 | 0 | 696 B |
| #6529 | RunOnMethodBegin |
netcoreapp3.1 | 895ns | 0.419ns | 1.62ns | 0.00941 | 0 | 0 | 696 B |
| #6529 | RunOnMethodBegin |
net472 | 1.1μs | 1.58ns | 6.12ns | 0.104 | 0 | 0 | 658 B |
NachoEchevarria
changed the title
anna-git
reviewed
Jan 14, 2025
| } | ||
| catch (ObjectDisposedException) | ||
| { | ||
| _contextUninitialized = true; |
anna-git
reviewed
Jan 14, 2025
| SecurityReporter.LogAddressIfDebugEnabled(args); | ||
| IResult? result = null; | ||
|
|
||
| try | ||
| { | ||
| var additiveContext = _httpTransport.GetAdditiveContext(); |
There was a problem hiding this comment.
isn't the problem potentially still here? If the httpcontext is concurrently disposed right before calling GetAdditiveContext on l.60.. (and potentially on the SetAdditiveContext )
I'm wondering if the try catch shouldnt directly be in GetAdditiveContext of SecurityCoordinator.Core ?
There was a problem hiding this comment.
The problem is that the context can be disposed at anytime while we use it. With this change, we are handling most of the errors that we are encountering, but it could happen what you just mentioned. On the other hand, checking for a disposed context anytime that we use it would have some performance impact and even that could not guarantee 100% that we are not getting more exceptions (if the context is disposed right after checking and before actually using it).
We could also try/catch any access to the context features (which includes almost every property associated to the context, request and response). In my first approach, I was doing that, but many code changes were required and, being practical, all the detected exceptions are happening in the same place, so I decided to protect just the problematic section. Do you think that try/catching any access to the context would be a better solution?
In the end, we probably will need to do a big refactor of our code to avoid accessing the context so often.
anna-git
approved these changes
Jan 15, 2025
e-n-0
approved these changes
Jan 15, 2025
|
Thank you for your feedback and reviews! |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Summary of changes
We are getting (on netcore only) some ObjectDisposedExceptions when calling the WAF.
Some stack examples:
The number of orgs that suffer from it is small. It seems that we are tying to access the HttpContext after disposal. This launches an exception when trying to access the features of the context.
The method Uninitialize() of the class DefaultHttpContext is called when the request finishes:
When we try to access some values from the context such as the return code, we eventually get this exception.
Why this could happen? Two possible explanations have been identified:
If we detect that the context has been uninitialized, we should stop using it. Unfortunately, there is no reliable way to detect if the context is disposed before getting it's features. In the previous Uninitialize method, the field _active is private. We cannot get the features without getting the exception and the fields _response, _request, _connection and _websockets set their features to default, but these feature fields are not exposed. Given that, we can only capture the exception and assume that the context has been disposed and we should not try to access it anymore (or use reflection).
Some sample code has been added to our sample pages in order to reproduce the situation.
In .net framework, we are not getting these exceptions when trying to access the context with a similar code. This is consistent with the results got from the telemetry logs.
While we are accessing the context in several parts of our code, it seems that all the exceptions observed were thrown in the method RunWaf(). No other ObjectDisposed exception was found out of this scope so, for now, we are protecting only this part of the code.
The sample code that calls the manual uninitialization of the tracer would also make the Asp.Netcore framework to launch an exception after finishing the request. This exception prevents the tracer to close the root span.
Reason for change
Implementation details
Test coverage
Other details