Skip to content

Disable automatic logs injection during IIS PreStartInit phase#1157

Merged
zacharycmontoya merged 10 commits into
masterfrom
zach/iis/preinitstart_via_profiler
Jan 29, 2021
Merged

Disable automatic logs injection during IIS PreStartInit phase#1157
zacharycmontoya merged 10 commits into
masterfrom
zach/iis/preinitstart_via_profiler

Conversation

@zacharycmontoya

@zacharycmontoya zacharycmontoya commented Jan 21, 2021

Copy link
Copy Markdown
Contributor

Replaces #1139

Issue

This change fixes a crash that occurs under the following conditions:

  1. .NET Framework application is hosted in IIS
  2. Automatic logs injection is enabled
  3. Application uses the log4net logging library
  4. Automatic instrumentation is triggered during the IIS PreStartInit phase

Context

In order to store ambient information for the logging context on .NET Framework, log4net uses CallContext. The first time a property is stored, a log4net dictionary type is created and permanently stored in the CallContext, even if the dictionary is later found to be empty. This creates an error condition: If this is stored into the CallContext during the IIS PreStartInit phase (which occurs in the application-specific AppDomain), then a crash will occur when the phase is finished and execution resumes in the IIS default AppDomain.

Solution

The solution is two-fold:

  1. When automatic instrumentation is enabled, we already perform IL rewriting at the beginning of the IIS PreStartInit code path to load our managed code. Modify this code path to begin and end with a call to AppDomain.SetData to set a flag that indicates if the IIS PreStartInit phase is still running. This flag can be observed from elsewhere in the AppDomain and need not be on the same thread.
  2. Register to a new TraceStarted event provided by the ScopeManager and register a callback to evaluate whether we're still running in this PreStartInit phase. It will either check for the AppDomain flag (if it was not-null) or it will fallback to checking the StackTrace (which is expensive). As soon as we detect false, we won't execute these checks again.

Optimizations to this strategy include never subscribing to the TraceStarted event if one of the following conditions is met at Tracer startup:

  1. Automatic instrumentation is enabled and the IIS PreStartInit flag is already false
  2. No automatic instrumentation is enabled and the process name is not w3wp or iisexpress

Testing

  1. Added automatic instrumentation + logs injection to IIS smoke test in CI/CD (project: Samples.AspNet472.LoaderOptimizationRegKey)
  2. Tested locally with logs injection enabled and traces started in the IIS PreInitStart phase for both 1) IIS | IIS Express and 2) Automatic Instrumentation | Custom Instrumentation

Benchmarks

Observations from the below numbers:

  • The only performance penalty is when LogsInjectionEnabled=true and starting multiple traces inside the IIS PreStartInit phase of execution. Though, we expect this to be the rare case anyways.
  • AppDomain.SetData / AppDomain.GetData check, which is used when automatic instrumentation is enabled, is at least 2x faster than the StackTrace walk. The StackTrace check is only needed when automatic instrumentation is not enabled, so this should be the rare case.

Code without the Tracer and scenario setup done in [GlobalSetup] before the iteration:

        [Benchmark]
        public int OpenTracesWithLogsInjectionEnabled()
        {
            int retVal = 0;

            for (int i = 0; i < NumberOfTraces; i++)
            {
                using (var scope = tracer.StartActive("iteration"))
                {
                    retVal++;
                }
            }

            return retVal;
        }

Scenario: LogsInjectionEnabled=false

State AutomaticInstr NumberOfTraces Mean Error StdDev Median Gen 0 Allocated
NotIIS False 5 4.203 μs 0.0837 μs 0.1941 μs 4.209 μs 0.6180 2.86 KB
NotIIS False 10 8.185 μs 0.1601 μs 0.2138 μs 8.057 μs 1.2360 5.72 KB
NotIIS False 25 20.413 μs 0.2383 μs 0.2113 μs 20.355 μs 3.0823 14.3 KB
NotIIS True 5 4.196 μs 0.0834 μs 0.1084 μs 4.160 μs 0.6180 2.86 KB
NotIIS True 10 8.190 μs 0.0611 μs 0.0477 μs 8.194 μs 1.2360 5.72 KB
NotIIS True 25 20.724 μs 0.2628 μs 0.2458 μs 20.731 μs 3.0823 14.3 KB
IISNotPreStart False 5 4.099 μs 0.0754 μs 0.0706 μs 4.070 μs 0.6180 2.86 KB
IISNotPreStart False 10 8.343 μs 0.0832 μs 0.0778 μs 8.351 μs 1.2360 5.72 KB
IISNotPreStart False 25 20.504 μs 0.4028 μs 0.4795 μs 20.407 μs 3.0823 14.3 KB
IISNotPreStart True 5 4.198 μs 0.0789 μs 0.0844 μs 4.232 μs 0.6180 2.86 KB
IISNotPreStart True 10 8.106 μs 0.1070 μs 0.0894 μs 8.075 μs 1.2360 5.72 KB
IISNotPreStart True 25 20.479 μs 0.4094 μs 0.7383 μs 20.158 μs 3.0823 14.3 KB
IISPreStart False 5 4.228 μs 0.0805 μs 0.1569 μs 4.193 μs 0.6180 2.86 KB
IISPreStart False 10 8.399 μs 0.1649 μs 0.3586 μs 8.288 μs 1.2360 5.72 KB
IISPreStart False 25 20.874 μs 0.3948 μs 0.4388 μs 20.754 μs 3.0823 14.3 KB
IISPreStart True 5 4.134 μs 0.0815 μs 0.1245 μs 4.115 μs 0.6180 2.86 KB
IISPreStart True 10 8.097 μs 0.0651 μs 0.0543 μs 8.096 μs 1.2360 5.72 KB
IISPreStart True 25 21.767 μs 0.3984 μs 0.3727 μs 21.721 μs 3.0823 14.3 KB

Scenario: LogsInjectionEnabled=true

State AutomaticInstr NumberOfTraces Mean Error StdDev Median Gen 0 Allocated
NotIIS False 5 7.768 μs 0.0961 μs 0.0852 μs 7.772 μs 1.4343 6.66 KB
NotIIS False 10 15.735 μs 0.2832 μs 0.2365 μs 15.757 μs 2.8687 13.32 KB
NotIIS False 25 40.418 μs 0.7801 μs 1.4460 μs 40.113 μs 7.2021 33.3 KB
NotIIS True 5 8.021 μs 0.1447 μs 0.1283 μs 8.003 μs 1.4343 6.66 KB
NotIIS True 10 15.484 μs 0.2796 μs 0.2615 μs 15.387 μs 2.8687 13.32 KB
NotIIS True 25 39.060 μs 0.7682 μs 0.8220 μs 38.811 μs 7.2021 33.3 KB
IISNotPreStart False 5 7.911 μs 0.1498 μs 0.1784 μs 7.895 μs 1.4343 6.66 KB
IISNotPreStart False 10 15.590 μs 0.3103 μs 0.3573 μs 15.626 μs 2.8687 13.32 KB
IISNotPreStart False 25 38.816 μs 0.5025 μs 0.4454 μs 38.716 μs 7.2021 33.3 KB
IISNotPreStart True 5 7.775 μs 0.0994 μs 0.0881 μs 7.756 μs 1.4343 6.66 KB
IISNotPreStart True 10 16.035 μs 0.3162 μs 0.4634 μs 15.901 μs 2.8687 13.32 KB
IISNotPreStart True 25 40.042 μs 0.5196 μs 0.4339 μs 39.943 μs 7.2021 33.3 KB
IISPreStart False 5 143.702 μs 2.7051 μs 2.5303 μs 143.335 μs 10.2539 47.97 KB
IISPreStart False 10 289.001 μs 5.3822 μs 5.2860 μs 287.355 μs 20.5078 95.91 KB
IISPreStart False 25 728.805 μs 12.5603 μs 12.8985 μs 726.538 μs 51.7578 239.88 KB
IISPreStart True 5 62.554 μs 0.9244 μs 0.7719 μs 62.470 μs 2.4414 11.69 KB
IISPreStart True 10 129.738 μs 2.5527 μs 3.0388 μs 130.842 μs 4.8828 23.38 KB
IISPreStart True 25 309.804 μs 2.6852 μs 2.0964 μs 310.451 μs 12.2070 58.48 KB

@DataDog/apm-dotnet

@zacharycmontoya
zacharycmontoya requested a review from a team as a code owner January 21, 2021 22:56
@zacharycmontoya zacharycmontoya changed the title Zach/iis/preinitstart via profiler Disable automatic logs injection during IIS PreStartInit phase Jan 21, 2021
}

private void SetLogContext(string service, string version, string env, ulong traceId, ulong spanId)
private void SetLogContext(ulong traceId, ulong spanId)

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.

Additional unrelated change I made while I was here: The service, version, and env of the Tracer never change, so I removed those argument from the method.

return hr;
}

ULONG string_len = 0;

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.

Another unrelated change, string_contents was never used anywhere so I deleted. It was probably used for debugging at some point

@tonyredondo tonyredondo 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.

LGTM, glad to see the AppDomain.SetData outperforming...

}

if (is_desktop_iis) {
hr = AddIISPreStartInitFlags(module_id,

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.

😅 another method to port to ReJIT when I start to work in NGEN images support... hehe

@tonyredondo
tonyredondo requested a review from a team January 28, 2021 16:45
@zacharycmontoya
zacharycmontoya force-pushed the zach/iis/preinitstart_via_profiler branch from ab4f2eb to 2f3b4d3 Compare January 29, 2021 01:47
Comment on lines +2521 to +2529
#ifdef _WIN32
LPCWSTR pre_init_start_str = L"Datadog_IISPreInitStart";
auto pre_init_start_str_size = wcslen(pre_init_start_str);
#else
char16_t pre_init_start_str[] =
u"Datadog_IISPreInitStart";
auto pre_init_start_str_size =
std::char_traits<char16_t>::length(pre_init_start_str);
#endif

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.

At some point we should think of introducing a macro for those

var initialStackFrame = stackTrace.GetFrame(stackTrace.FrameCount - 1);
var initialMethod = initialStackFrame.GetMethod();

_executingIISPreStartInit = initialMethod.DeclaringType.FullName.Equals("System.Web.Hosting.HostingEnvironment", StringComparison.OrdinalIgnoreCase)

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.

After the value transitions back to false, can't you unsubscribe the RefreshIISPreAppState handler?

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.

Yes you're right. I'll add that

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.

@kevingosse do you know if there are any caveats of removing the event handler while the same event handler is still running?

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.

Done in aacd0a0

}
else
{
_performAppDomainFlagChecks = false;

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.

As this can have a performance impact, I believe we should add a warning log when _performAppDomainFlagChecks is false

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.

Sounds good, will add

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.

@kevingosse I made the change in c5c9c63 . Is that good for you?

@kevingosse

Copy link
Copy Markdown
Contributor

LGTM, I'd just like to add one log

Comment thread build/docker/IIS/build.ps1 Outdated
@zacharycmontoya
zacharycmontoya merged commit d63cf29 into master Jan 29, 2021
@zacharycmontoya
zacharycmontoya deleted the zach/iis/preinitstart_via_profiler branch January 29, 2021 23:57
@zacharycmontoya zacharycmontoya added this to the 1.23.0 milestone Feb 3, 2021
@zacharycmontoya zacharycmontoya added the area:tracer The core tracer library (Datadog.Trace, does not include OpenTracing, native code, or integrations) label Feb 3, 2021
pjanotti added a commit to open-telemetry/opentelemetry-dotnet-instrumentation that referenced this pull request Feb 15, 2021
* Catchup to Upstream

Update .NET tracer to 1.22.1-prerelease (DataDog/dd-trace-dotnet#1172)

Ignore agent and port when in AAS (dogstatsd) (DataDog/dd-trace-dotnet#1174)

Patch .NET 5.0 SDK cert issue (DataDog/dd-trace-dotnet#1175)

As described in NuGet/Announcements#49 and NuGet/Home#10491

Fix drive space issues related to sample projects (DataDog/dd-trace-dotnet#1171)

Exclude the profilers when buiding samples
This avoids copying 100s of MB per sample
Instead, they will load from the IntegrationTests output folder
Disables shadow copy ing the integration tests

Add MacOS support for runner/standalone tool (DataDog/dd-trace-dotnet#1136)

Adds MacOS profiler to the tool and the standalone app

fix runner

clean artifacts

Changes

MySql CallTarget integration (DataDog/dd-trace-dotnet#1168)

Initial commit for MySql instrumentation.

Fix CallTarget span count

update integrations.json

Npgsql CallTarget integration (DataDog/dd-trace-dotnet#1164)

Initial migration for Npgsql to CallTarget.

Test changes

Update Integrations.json file

Update the expected span count for calltarget instrumentation.

Update src/Datadog.Trace.ClrProfiler.Managed/AutoInstrumentation/AdoNet/Npgsql/NpgsqlConstants.cs

Co-authored-by: Zach Montoya [email protected]

update integrations.json
Co-authored-by: Zach Montoya [email protected]

Add missing delete[] instructions. (DataDog/dd-trace-dotnet#1177)

Add instrumentation for HttpWebRequest.GetRequestStream (DataDog/dd-trace-dotnet#1106)

Exponential Backoff Named Pipe Check (DataDog/dd-trace-dotnet#1176)

Refactor ADO.NET integrations to use the assembly integration attribute (DataDog/dd-trace-dotnet#1173)

Refactor all ADO.NET integrations to use the Assembly attribute.

Applies changes from review.

Changes from review

Add a better exception message on GenerateIntegrationDefinitions

fix typo

update integrations.json

Fix compilation and refactor MySql and Npgsql to the new integration format.

Disable automatic logs injection during IIS PreStartInit phase (DataDog/dd-trace-dotnet#1157)

This change fixes a crash that occurs under the following conditions:

.NET Framework application is hosted in IIS
Automatic logs injection is enabled
Application uses the log4net logging library
Automatic instrumentation is triggered during the IIS PreStartInit phase
In order to store ambient information for the logging context on .NET Framework, log4net uses CallContext. The first time a property is stored, a log4net dictionary type is created and permanently stored in the CallContext, even if the dictionary is later found to be empty. This creates an error condition: If this is stored into the CallContext during the IIS PreStartInit phase (which occurs in the application-specific AppDomain), then a crash will occur when the phase is finished and execution resumes in the IIS default AppDomain.

The solution is two-fold:

When automatic instrumentation is enabled, we already perform IL rewriting at the beginning of the IIS PreStartInit code path to load our managed code. Modify this code path to begin and end with a call to AppDomain.SetData to set a flag that indicates if the IIS PreStartInit phase is still running. This flag can be observed from elsewhere in the AppDomain and need not be on the same thread.
Register to a new TraceStarted event provided by the ScopeManager and register a callback to evaluate whether we're still running in this PreStartInit phase. It will either check for the AppDomain flag (if it was not-null) or it will fallback to checking the StackTrace (which is expensive). As soon as we detect false, we won't execute these checks again.
Optimizations to this strategy include never subscribing to the TraceStarted event if one of the following conditions is met at Tracer startup:

Automatic instrumentation is enabled and the IIS PreStartInit flag is already false
No automatic instrumentation is enabled and the process name is not w3wp or iisexpress
[AAS] Enable DD_LOG_LEVEL with DD_TRACE_DEBUG (DataDog/dd-trace-dotnet#1178)

Fix WinHttpHandlerIntegration (DataDog/dd-trace-dotnet#1170)

minor: fix logs in sample app
minor: fix documentation
Restructure HttpMessageHandlerTests to test all instrumentations
HttpClientHandler
SocketsHttpHandler
WinHttpHandler

Including when HttpClientHandler is not used, and when the SocketsHttpHandler is disabled.

Fix WinHttpHandlerIntegration
WinHttpHandlerIntegration was not working in tests previously. This fixes the integartion tests so that we correctly instrument WinHttpHandler

As of .NET 5.0, WinHttpHandler lives in a separate assembly: https://docs.microsoft.com/dotnet/core/compatibility/networking/5.0/winhttphandler-removed-from-runtime

Fix ServiceMappingTests
This was using the HttpMessageHandler sample, but that was made much more complex, so switch to reusing WebRequest for simplicity

Add Curl to alpine 2.x-3.x images
When DOTNET_SYSTEM_NET_HTTP_USESOCKETSHTTPHANDLER is "0", HttpClientHandler uses the "native" handler, which is CurlHandler on linux
Alpine doesn't have curl by default, so will throw TypeInitializationException unless it's added

AAS Prerelease 1.22.2 (DataDog/dd-trace-dotnet#1180)

CIApp Specs tests (DataDog/dd-trace-dotnet#1154)

Add json data

Add Ci environment variable tests from https://github.com/DataDog/datadog-ci-spec

MsTestV2 CallTarget integration (DataDog/dd-trace-dotnet#1132)

MsTestV2 CallTarget Instrumentation

Update integrations.json

Fix from rebase

Change the folder structure with a new Testing parent folder.

update integrations.json

Changes from the review

update integrations.json

Publish the profiler logs as artifact instead of tailing them (DataDog/dd-trace-dotnet#1181)

Bump the .NET Tracer version to 1.23.0 (DataDog/dd-trace-dotnet#1185)

Add support for synchronous HttpClient.Send() (DataDog/dd-trace-dotnet#1162)

Add HttpClientHandler sync Send integration
Virtually identical to SendAsync integration, so extracted common code to HttpClientHandlerCommon
Kept existing HttpClientHandlerIntegration name for back compat reasons
Only available in .NET 5.0 +

Add SocketsHttpHandler sync CallTarget integration

Add HttpClient.Send() tests

Fix environment variables overwrite. (DataDog/dd-trace-dotnet#1182)

Refactor regression test to expose / remove unused Datadog.Trace.AspNet code (DataDog/dd-trace-dotnet#1160)

The Log4Net.SerializationException regression test does the bare minimum to simulate the IIS PreStartInit phase to make sure that initializing a Tracer with LogsInjectionEnabled=true doesn't crash with a SerializationException. Refactor to remove a code path that is no longer used in the Datadog.Trace.AspNet.

Add Area tag to ASP.NET integration (DataDog/dd-trace-dotnet#1183)

Add area support for aspnet MVC + WebApi2 integration
Add area to AspNetMvc4 sample
Enhance AspNet tests to check correct tags are added, and to test areas
Implement log rate limiting as per RFC (DataDog/dd-trace-dotnet#1153)

Replace Log.Verbose with Log.Debug

Update the minimum log level to Debug

The RFC only uses Debug, Warn, and Error. We add Information, for emitting non-error logs (such as configuration status logs)

Update some log levels to closer align with the RFC

Add IDataDogLogger wrapper around ILogger

We'll use this to control which log levels etc are available, add rate limiting etc.
For now, implements all currently used APIs of ILogger

Add method for retrieving IDatadogLogger
Unfortunately, despite being internal, we can't change the DatadogLogging class as it will cause MethodNotFound exceptions when there's a mismatch between Manual and Automatic packages.
Instead, mark the old methods obsolete, and add new preferred methods to use.

Replace usages of ILogger with IDatadogLogger

Make IDatadogLogger interface consistent across log levels

Ensuring we don't box and allocate unnecessarily makes the interface quite verbose unfortunately.
Replace use of params. This makes for an awkward interface for callers when many parameters are used, as you must pre-allocate the array at the call site.
Removing the use of params is necessary so that we can rate limit using [CallerFilePath], which requires optional parameters, and so are not compatible with params arguments

Add [CallerLineNumber] and [CallerFilePath] attributes
Required for the log rate limiting RFC.
Unfortunately, means that some logging calls will be ambiguous unless you specify generic arguments, which is not ideal.
Placed the LineNumber attribute first, as more common to have a string argument than an int argument

Add LogRateLimiter to ensure we only write a given log X times per second
Based on the APM Tracer Logging RFC
The default (null) implementation doesn't filter any log messages
All log messages that are written indicate how many previous instances were skipped

Allow controlling rate limiting with DD_LOGGING_RATE, as per RFC

Replace SafeLogError with Error

As we now have a wrapper for the ILogger, no reason to have a separate logging extension, as can make all logging events safe
The extension was not compatible with the CallerMemberName attribute so would need updating anyway
Confirmed with a microbenchmark that the extra overhead of adding the try-catch for every log event should be negligible + it's only there when the log level is enabled anyway

Remove unused extension
Doesn't add anything over calling _logger.Error directly, and hides caller member name attributes

Propogate caller member attributes in logging extensions
Necessary for rate limiter to throttle based on original call site, otherwise all logs that call the extension would be throtted together

Handle circular static logger initialization in EnvironmentHelpers
DatadogLogging creates a shared logger instance. Creating this instance requires using EnvironmentHelpers.
This in turn tries to get the DataDogLogging.SharedLogger
This is initially set to a "null" logging implementation, and will remain as such for the lifetime of the program
Using a Lazy<> means the logger is only retrieved when ther's an exception in EnvironmentHelpers, hopefully after SharedLogger has been updated

Rollback CallerMemberAttributes in CallTargetInvoker.LogException
Not entirely sure how to get these to hook to work, or if it's even possible...

Replace empty array with Datadog.Trace.Util.ArrayHelper.Empty
Co-authored-by: Kevin Gosse [email protected]

No need to use Select( x=> x.ToSring())
Co-authored-by: Kevin Gosse [email protected]

PR review fixes
Revert log level change
Fix rate value guard
Don't add "skip count" message if skipCount == 0
Add comments
Fix usage of Clock in tests
LogRateBucketInfo can be readonly struct
Use struct as key for dictionary
Add escape hatch if CallerLineNumber attributes fails for some reason

Fix merge issue

Fix rate limit

Co-authored-by: Zach Montoya [email protected]

Bail-out of LogRateLimiter if either filepath or line number is empty
Co-authored-by: Kevin Gosse [email protected]
Co-authored-by: Zach Montoya [email protected]

Fix some diagnostic warnings in tests (DataDog/dd-trace-dotnet#1197)

Fix xUnit complaining about unserializable tests

Fix duplicate collection definition

Properly disable parallelization in CIEnvironmentVariableTests (DataDog/dd-trace-dotnet#1198)

Properly drain stdout/stderr in integration tests (DataDog/dd-trace-dotnet#1192)

Properly drain stdout/stderr in integration tests
Add diagnostics
Change the folder structure to use an Http parent folder. (DataDog/dd-trace-dotnet#1196)

Update integrations.json version (and fix version numbers broken in
DataDog/dd-trace-dotnet@d72b04c)

Make tool/standalone build wait on MacOS profiler build (DataDog/dd-trace-dotnet#1202)

Remove the Analyzed Span flag on Benchmarks instrumentation (DataDog/dd-trace-dotnet#1179)

Fix RequestReJIT deadlock. (DataDog/dd-trace-dotnet#1203)

Initial work to request rejit in a custom thread.

Adding shutdown mechanism.

Comment shutdown temporarily.

remove warnings.

Add support for mdMethodDef array.

formatting: missing space.

Call RejitHandler Shutdown() to stop custom thread before profiler shutdown.

Make the diagnostic log fully fire-and-forget (DataDog/dd-trace-dotnet#1169)

Avoids a case where it would lead to the HttpMessageHandler integration being called from the Tracer constructor, which in turns would call Tracer.Instance, creating a second instance of the tracer.

Update README with current links (DataDog/dd-trace-dotnet#1200)

Use DD_TRACE_LOGGING_RATE instead of DD_LOGGING_RATE (DataDog/dd-trace-dotnet#1207)

Fix MaximumVersion xml comment (DataDog/dd-trace-dotnet#1209)

Manual cherry-pick corrections

Remove deprecated method from ZipkinApi
andrewlock added a commit that referenced this pull request Oct 31, 2024
## Summary of changes

Adds a check that IisPreStartInit has completed before we run any
automatic instrumentations

## Reason for change

We recently had a case where a customer was [using
`AzureKeyVaultConfigBuilder`](https://github.com/aspnet/MicrosoftConfigurationBuilders/blob/main/src/Azure/AzureKeyVaultConfigBuilder.cs)
with ASP.NET's web.config to load configuration into `AppSettings`,
which was causing the application to deadlock on startup.

After some investigation, we isolated the problem as happening
specifically when there are 2 apps running inside an app pool:

- App 1 starts
  - The config builder populates and loads from key vault
  - We initialize the tracer, and set up instrumentation
  - App1 works fine 👍 
- App 2 starts
  - The config builder tries to populate and load from key vault
    - This requires making HTTP requests
- Due to the instrumentation run for app 1, we instrument the HTTP
request
- This invokes `CallTargetInvoker` which tries to initialize the tracer
- Initializing the tracer [requires reading `AppSettings` so that we can
populate
configuration](https://github.com/DataDog/dd-trace-dotnet/blob/c8399df44468f83c22a978418e0cfc314f9c3542/tracer/src/Datadog.Trace/Configuration/ConfigurationSources/GlobalConfigurationSource.cs#L39)
      - The config builder tries to populate and load from key vault 
      - ♻️re-entry 💥


![boom](https://github.com/user-attachments/assets/725ec7ba-a1ff-4069-aa15-f5dd3d28c314)

So the key thing is that we need to make sure we _don't_ run our
automatic instrumentation until _after_ the IIS pre-init stage is
completely, to avoid re-entry and recursion during setup.

## Implementation details

The implementation is leveraging work we did years ago to fix
essentially the same problem:
#1157. The problem back
then was with Liblog and NLog, but we did all the work to inject flags
for tracking when it is safe to make changes.

Given the native work already exists, we can piggy-pack on those hooks
and make sure we don't run any automatic instrumentations unless the
domain as finished pre-initialization.

This is still _relatively_ fragile, as things like adding a static
reference to IDatadogLogger would cause a static initialization to
happen too early, and ultimately deadlock/crash the app, so added a
bunch of comments to try to highlight the issue

## Test coverage

This is kind of a pain to test because it requires a custom config
builder, plus two applications running in an app pool. I tested manually
by

- Created a custom `ConfigBuilder` based on the
`AzureKeyVaultConfigBuilder` implementation. The custom builder simply
makes a generic HTTP request when a value is requested
- Create a generic .NET 472 asp.net app
- Add to the `web.config` to set up the builder (see below)
- Publish the app
- Create two asp.net apps in IIS, using the same app pool
- Hit the first app - all good 👍 
- Hit the second app - 💥 `The configBuilder 'CustomBuilder' failed while
processing the configuration section 'appSettings'.: The
ConfigurationBuilder
'CustomBuilder[Microsoft.Configuration.ConfigurationBuilders.CustomConfigBuilder]'
has recursively re-entered processing of the 'appSettings' section` (I
based my implementation on v3 which specifically detects re-entry)
- Made the fix, now it works 🎉 

web.config for my dummy test:
```xml
<configuration>
  <configSections>
    <section name="configBuilders"
      type="System.Configuration.ConfigurationBuildersSection, 
      System.Configuration, Version=4.0.0.0, Culture=neutral, 
      PublicKeyToken=b03f5f7f11d50a3a"
      restartOnExternalChanges="false" requirePermission="false" />
  </configSections>

  <configBuilders>
    <builders>
      <add name="CustomBuilder" preloadSecretNames="false" Uri="https://some-value-prd.vault.azure.net/"
      type="Microsoft.Configuration.ConfigurationBuilders.CustomConfigBuilder, CustomConfigBuilder, Version=1.0.0.0, Culture=neutral" />
    </builders>
  </configBuilders>

  <appSettings configBuilders="CustomBuilder">
    <add key="DummyKey1" value="DummyKey1 value from web.config" />
    <add key="DummyKey2" value="DummyKey2 value from web.config" />
  </appSettings>
```

Complete test solution is here:

[ConfigBuilderIssueRepro.zip](https://github.com/user-attachments/files/17343990/ConfigBuilderIssueRepro.zip)

## Other details

Fixes: https://datadoghq.atlassian.net/browse/APMS-13426
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

area:tracer The core tracer library (Datadog.Trace, does not include OpenTracing, native code, or integrations) type:bug

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants