Disable automatic logs injection during IIS PreStartInit phase#1157
Conversation
| } | ||
|
|
||
| private void SetLogContext(string service, string version, string env, ulong traceId, ulong spanId) | ||
| private void SetLogContext(ulong traceId, ulong spanId) |
There was a problem hiding this comment.
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; |
There was a problem hiding this comment.
Another unrelated change, string_contents was never used anywhere so I deleted. It was probably used for debugging at some point
tonyredondo
left a comment
There was a problem hiding this comment.
LGTM, glad to see the AppDomain.SetData outperforming...
| } | ||
|
|
||
| if (is_desktop_iis) { | ||
| hr = AddIISPreStartInitFlags(module_id, |
There was a problem hiding this comment.
😅 another method to port to ReJIT when I start to work in NGEN images support... hehe
ab4f2eb to
2f3b4d3
Compare
| #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 |
There was a problem hiding this comment.
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) |
There was a problem hiding this comment.
After the value transitions back to false, can't you unsubscribe the RefreshIISPreAppState handler?
There was a problem hiding this comment.
Yes you're right. I'll add that
There was a problem hiding this comment.
@kevingosse do you know if there are any caveats of removing the event handler while the same event handler is still running?
| } | ||
| else | ||
| { | ||
| _performAppDomainFlagChecks = false; |
There was a problem hiding this comment.
As this can have a performance impact, I believe we should add a warning log when _performAppDomainFlagChecks is false
There was a problem hiding this comment.
Sounds good, will add
There was a problem hiding this comment.
@kevingosse I made the change in c5c9c63 . Is that good for you?
|
LGTM, I'd just like to add one log |
* 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
## 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 💥  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
Replaces #1139
Issue
This change fixes a crash that occurs under the following conditions:
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 theCallContext, even if the dictionary is later found to be empty. This creates an error condition: If this is stored into theCallContextduring 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:
AppDomain.SetDatato 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.TraceStartedevent 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
TraceStartedevent if one of the following conditions is met at Tracer startup:w3wporiisexpressTesting
Samples.AspNet472.LoaderOptimizationRegKey)Benchmarks
Observations from the below numbers:
AppDomain.SetData/AppDomain.GetDatacheck, 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:Scenario: LogsInjectionEnabled=false
Scenario: LogsInjectionEnabled=true
@DataDog/apm-dotnet