Exponential Backoff Named Pipe Check#1176
Conversation
| if (pipeIsBound) | ||
| { | ||
| // It is possible that if a pipe is bound it may still be shutting down from last time | ||
| // Check on a delay to be sure we have the agent available | ||
| var attempts = 7; | ||
| var delay = 50d; | ||
|
|
||
| while (--attempts > 0) | ||
| { | ||
| await Task.Delay((int)delay); | ||
| if (!metadata.NamedPipeIsBound()) | ||
| { | ||
| metadata.ProcessState = ProcessState.ReadyToStart; | ||
| break; | ||
| } | ||
|
|
||
| // Should result in a max delay of ~3.28 seconds before giving up | ||
| delay = delay * 1.75d; | ||
| } | ||
|
|
||
| metadata.ProcessState = ProcessState.Healthy; | ||
| } | ||
| else | ||
| { | ||
| // If no pipe is bound, kick it off | ||
| metadata.ProcessState = ProcessState.ReadyToStart; | ||
| } |
There was a problem hiding this comment.
So if the pipe is bound, and remains so, does that mean we'll lose 3+ seconds at the start? That seems like quite a lot? Or do we use the pipe if it's available?
There was a problem hiding this comment.
We use the pipe if it's available.
Currently, if there is a conflict on the first try, we lose stats for ~10 seconds.
This conflict arises if a named pipe has not been cleaned up from a previous instance.
The first process start fails because the named pipe is not available to bind to, and the next retry doesn't come through for 10 seconds, even though the pipe might be cleared in 100ms.
This mechanism is to check the named pipe in quicker intervals on startup.
If a named pipe is bound, it will check in 50ms, then 87ms, then 153 ms, and so on until a max wait of 1436ms, which sums to approximately 3.28 seconds.
Another improvement here which is less obvious, the first failed attempt goes away.
Previously, we were deciding to start if the process was not running, but the named pipe remains around after process kill in testing, so the named pipe being bound is a more accurate timing check.
This means no more (or at least incredibly rare) transient error messages on startup.
There was a problem hiding this comment.
Ah ok, I think the point I was missing is that there's (presumably) no way for a pipe to transition from bound -> unbound -> bound inside the ProcessState.NotRunning branch. You'll only ever see a bound -> unbound transition (as it's rebound in the ProcessState.Healthy || ProcessState.Faulted branch).
There was a problem hiding this comment.
Unless there are multiple processes or even app domains running. :)
There was a problem hiding this comment.
ok... then if that is a possibility, (bound -> unbound -> bound), then there's potential for a race condition here where you wait for 3s unnecessarily right? I'm not sure if a) if that's even avoidable without the long lived process approach, b) if it's a problem 🙂
There was a problem hiding this comment.
Yes, any separate process or app domain will run into this delay for this task.
This is totally acceptable to me, as it doesn't block the application and makes the agent processes much more robust.
| if (metadata.ProcessIsHealthy()) | ||
| { | ||
| // Should result in a max delay of ~3.28 seconds before giving up | ||
| delay = delay * 1.75d; |
There was a problem hiding this comment.
:thonk: what is the origin of the magic number?
There was a problem hiding this comment.
Experimentation in a reasonable delay structure for making sure the process is started if the previous one drops.
Do you think this should be specifically documented?
lucaspimentel
left a comment
There was a problem hiding this comment.
LGTM. Some small tweaks to log messages.
* 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
Reduce transient named pipe conflicts in AAS.
Reduces timespan where stats are sent into the abyss.
netcore31
Tested cold startup.
Tested deployment over live app with concurrent requests which resulted in these logs for the trace agent as an example:
net472
Tested cold start.
Tested deploy over the top of framework app with concurrent requests.
Interestingly I have not hit the same code path in framework. Possibly it's a more clean cut over?
Either way, it works.
@DataDog/apm-dotnet