diff --git a/src/Elastic.Apm/AgentComponents.cs b/src/Elastic.Apm/AgentComponents.cs index cdeac9627..ef5362523 100644 --- a/src/Elastic.Apm/AgentComponents.cs +++ b/src/Elastic.Apm/AgentComponents.cs @@ -6,6 +6,7 @@ using System.Collections; using System.Collections.Generic; using System.Diagnostics; +using System.Threading; using Elastic.Apm.Api; using Elastic.Apm.BackendComm.CentralConfig; using Elastic.Apm.Config; @@ -234,14 +235,22 @@ internal static IApmLogger GetGlobalLogger(IApmLogger fallbackLogger, LogLevel a } var effectiveLogLevel = LogLevelUtils.GetFinest(agentLogLevel, fileLogConfig.LogLevel); - if ((fileLogConfig.LogTargets & GlobalLogTarget.File) == GlobalLogTarget.File) - TraceLogger.TraceSource.Listeners.Add(new TextWriterTraceListener(fileLogConfig.AgentLogFilePath)); - if ((fileLogConfig.LogTargets & GlobalLogTarget.StdOut) == GlobalLogTarget.StdOut) - TraceLogger.TraceSource.Listeners.Add(new TextWriterTraceListener(Console.Out)); - - var logger = new TraceLogger(effectiveLogLevel); - logger.Info()?.Log($"{nameof(fileLogConfig)} - {fileLogConfig}"); - return logger; + + // Guard against multiple calls within the same AppDomain (e.g. CreateDefaultLogger on .NET Framework + // calls GetGlobalLogger, then AgentComponents calls it again via the constructor). Without this guard + // each call would add a new TextWriterTraceListener to the shared static TraceSource, producing one + // log file per call instead of one per AppDomain. + if (Interlocked.Exchange(ref _fileLoggingSetupDone, 1) == 0) + { + if ((fileLogConfig.LogTargets & GlobalLogTarget.File) == GlobalLogTarget.File) + TraceLogger.TraceSource.Listeners.Add(new TextWriterTraceListener(fileLogConfig.AgentLogFilePath)); + if ((fileLogConfig.LogTargets & GlobalLogTarget.StdOut) == GlobalLogTarget.StdOut) + TraceLogger.TraceSource.Listeners.Add(new TextWriterTraceListener(Console.Out)); + + WriteFileHeader(fileLogConfig); + } + + return new TraceLogger(effectiveLogLevel); } catch (Exception e) { @@ -250,6 +259,37 @@ internal static IApmLogger GetGlobalLogger(IApmLogger fallbackLogger, LogLevel a return fallbackLogger; } + // Written once per AppDomain at file-logging setup time, bypassing the log-level filter so it always + // appears at the top of every agent.log regardless of the configured level. + private static void WriteFileHeader(GlobalLogConfiguration fileLogConfig) + { + var now = DateTime.Now; + var tid = Environment.CurrentManagedThreadId; + + void Emit(string message) + { + var line = $"[{now:yyyy-MM-dd HH:mm:ss.fff zzz}][{tid}][Info] - {message}"; + for (var i = 0; i < TraceLogger.TraceSource.Listeners.Count; i++) + { + var listener = TraceLogger.TraceSource.Listeners[i]; + if (!listener.IsThreadSafe) + lock (listener) + listener.WriteLine(line); + else + listener.WriteLine(line); + } + } + + Emit($"fileLogConfig - {fileLogConfig}"); + Emit($"AppDomain ID: {AppDomain.CurrentDomain.Id}"); + Emit($"AppDomain Name: {AppDomain.CurrentDomain.FriendlyName}"); + Emit($"AppDomain BaseDirectory: {AppDomain.CurrentDomain.BaseDirectory}"); + Emit($"AppDomain IsDefault: {AppDomain.CurrentDomain.IsDefaultAppDomain()}"); + TraceLogger.TraceSource.Flush(); + } + + private static int _fileLoggingSetupDone = 0; + #if NET || NETSTANDARD2_1 internal ElasticActivityListener ElasticActivityListener { get; } #endif diff --git a/src/Elastic.Apm/Config/ConfigurationLogger.cs b/src/Elastic.Apm/Config/ConfigurationLogger.cs index 6b002327e..cacf81957 100644 --- a/src/Elastic.Apm/Config/ConfigurationLogger.cs +++ b/src/Elastic.Apm/Config/ConfigurationLogger.cs @@ -69,6 +69,40 @@ public static void PrintAgentLogPreamble(IApmLogger logger, IConfigurationReader info.Log("Process ID: {ProcessId}", Process.GetCurrentProcess().Id); info.Log("Process Name: {ProcessName}", Process.GetCurrentProcess().ProcessName); info.Log("Command line arguments: '{ProcessArguments}'", string.Join(", ", System.Environment.GetCommandLineArgs())); + info.Log("AppDomain ID: {AppDomainId}", AppDomain.CurrentDomain.Id); + info.Log("AppDomain Name: {AppDomainFriendlyName}", AppDomain.CurrentDomain.FriendlyName); + info.Log("AppDomain BaseDirectory: {AppDomainBaseDirectory}", AppDomain.CurrentDomain.BaseDirectory); + info.Log("AppDomain IsDefault: {AppDomainIsDefault}", AppDomain.CurrentDomain.IsDefaultAppDomain()); +#if NETFRAMEWORK + try + { + info.Log("AppDomain Config File: {AppDomainConfigFile}", AppDomain.CurrentDomain.SetupInformation.ConfigurationFile); + info.Log("AppDomain Shadow Copy: {AppDomainShadowCopy}", AppDomain.CurrentDomain.SetupInformation.ShadowCopyFiles); + } + catch (Exception e) + { + info.Log("AppDomain setup info unavailable: {Error}", e.Message); + } + // Reflect against System.Web only if it is already loaded — avoids pulling the assembly into + // non-IIS processes (console apps, Windows services) where it has no business being loaded. + try + { + var systemWebAssembly = AppDomain.CurrentDomain.GetAssemblies() + .FirstOrDefault(a => string.Equals(a.GetName().Name, "System.Web", StringComparison.OrdinalIgnoreCase)); + var hostingEnvType = systemWebAssembly?.GetType("System.Web.Hosting.HostingEnvironment"); + var isHosted = hostingEnvType != null && (bool)(hostingEnvType.GetProperty("IsHosted")?.GetValue(null) ?? false); + info.Log("IIS Hosted: {IisHosted}", isHosted); + if (isHosted) + { + info.Log("IIS Site Name: {IisSiteName}", hostingEnvType.GetProperty("SiteName")?.GetValue(null) ?? ""); + info.Log("IIS Application Virtual Path: {IisVirtualPath}", hostingEnvType.GetProperty("ApplicationVirtualPath")?.GetValue(null) ?? ""); + } + } + catch (Exception e) + { + info.Log("IIS hosting info unavailable: {Error}", e.Message); + } +#endif info.Log("Operating System: {OSDescription}", RuntimeInformation.OSDescription); info.Log("CPU architecture: {OSArchitecture}", RuntimeInformation.OSArchitecture); info.Log("Host: {HostName}", System.Environment.MachineName); diff --git a/src/Elastic.Apm/Logging/GlobalLogConfiguration.cs b/src/Elastic.Apm/Logging/GlobalLogConfiguration.cs index 946bbbdfe..d32c9d03e 100644 --- a/src/Elastic.Apm/Logging/GlobalLogConfiguration.cs +++ b/src/Elastic.Apm/Logging/GlobalLogConfiguration.cs @@ -5,6 +5,7 @@ using System; using System.Collections; using System.Diagnostics; +using System.Globalization; using System.IO; using System.Linq; @@ -194,7 +195,9 @@ internal static GlobalLogConfiguration FromEnvironment(IDictionary environmentVa private static string GetLogFilePrefix() { var process = Process.GetCurrentProcess(); - return $"{process.ProcessName}_{process.Id}_{Environment.TickCount}"; + var appDomainId = AppDomain.CurrentDomain.Id; + var timestamp = DateTime.UtcNow.ToString("yyyyMMddTHHmmssfff", CultureInfo.InvariantCulture); + return $"{process.ProcessName}_{process.Id}_ad{appDomainId}_{timestamp}"; } public string CreateLogFileName(string applicationName = "agent") diff --git a/src/profiler/Elastic.Apm.Profiler.Managed.Loader/Startup.NetCore.cs b/src/profiler/Elastic.Apm.Profiler.Managed.Loader/Startup.NetCore.cs index f3a77bb60..7ea2789ef 100644 --- a/src/profiler/Elastic.Apm.Profiler.Managed.Loader/Startup.NetCore.cs +++ b/src/profiler/Elastic.Apm.Profiler.Managed.Loader/Startup.NetCore.cs @@ -54,6 +54,12 @@ private static Assembly ResolveDependencies(object sender, ResolveEventArgs args Logger.Log(LogLevel.Trace, "Probing: {0}, exists on disk: {1}", path, exists); + if (!exists) + { + Logger.Log(LogLevel.Debug, "AssemblyResolve: {0} not found in profiler directory, returning null", assemblyName.Name); + return null; + } + // Only load the main Elastic.Apm.Profiler.Managed.dll into the default Assembly Load Context. // If Elastic.Apm or other libraries are provided by the NuGet package, their loads are handled in the following two ways. // 1) The AssemblyVersion is greater than or equal to the version used by Elastic.Apm.Profiler.Managed, the assembly @@ -61,20 +67,27 @@ private static Assembly ResolveDependencies(object sender, ResolveEventArgs args // 2) The AssemblyVersion is lower than the version used by Elastic.Apm.Profiler.Managed, the assembly will fail to load // and invoke this resolve event. It must be loaded in a separate AssemblyLoadContext since the application will only // load the originally referenced version - if (exists) + try { if (assemblyName.Name.StartsWith("Elastic.Apm.Profiler.Managed", StringComparison.OrdinalIgnoreCase) && assemblyName.FullName.IndexOf("PublicKeyToken=ae7400d2c189cf22", StringComparison.OrdinalIgnoreCase) >= 0) { - Logger.Log(LogLevel.Debug, "Loading {0} assembly using Assembly.LoadFrom", assemblyName); - return Assembly.LoadFrom(path); + Logger.Log(LogLevel.Debug, "Loading {0} assembly using Assembly.LoadFrom", assemblyName.Name); + var assembly = Assembly.LoadFrom(path); + Logger.Log(LogLevel.Debug, "Loaded {0} from {1}", assemblyName.Name, assembly.Location); + return assembly; } - Logger.Log(LogLevel.Debug, "Loading {0} assembly using DependencyLoadContext.LoadFromAssemblyPath", assemblyName); - return DependencyLoadContext.LoadFromAssemblyPath(path); + Logger.Log(LogLevel.Debug, "Loading {0} assembly using DependencyLoadContext.LoadFromAssemblyPath", assemblyName.Name); + var depAssembly = DependencyLoadContext.LoadFromAssemblyPath(path); + Logger.Log(LogLevel.Debug, "Loaded {0} from {1}", assemblyName.Name, depAssembly.Location); + return depAssembly; + } + catch (Exception e) + { + Logger.Log(LogLevel.Error, e, "AssemblyResolve: failed to load {0} from {1}", assemblyName.Name, path); + return null; } - - return null; } } diff --git a/src/profiler/Elastic.Apm.Profiler.Managed.Loader/Startup.NetFramework.cs b/src/profiler/Elastic.Apm.Profiler.Managed.Loader/Startup.NetFramework.cs index 562052db7..2a5e5748e 100644 --- a/src/profiler/Elastic.Apm.Profiler.Managed.Loader/Startup.NetFramework.cs +++ b/src/profiler/Elastic.Apm.Profiler.Managed.Loader/Startup.NetFramework.cs @@ -53,10 +53,13 @@ private static bool IsNet472OrHigher() // Release value 461808 corresponds to .NET Framework 4.7.2 on Windows 10 1803+; // 461814 is the value for all other OS versions. Checking >= 461808 covers both. var release = Convert.ToInt32(key?.GetValue("Release") ?? 0); - return release >= 461808; + var result = release >= 461808; + Logger.Log(LogLevel.Debug, "IsNet472OrHigher: registry release={0}, result={1}", release, result); + return result; } - catch + catch (Exception e) { + Logger.Log(LogLevel.Warning, e, "IsNet472OrHigher: failed to read registry, assuming false"); return false; } } @@ -78,13 +81,24 @@ private static Assembly ResolveDependencies(object sender, ResolveEventArgs args Logger.Log(LogLevel.Trace, "Probing: {0}, exists on disk: {1}", path, exists); - if (exists) + if (!exists) { - Logger.Log(LogLevel.Debug, "Loading {0} assembly", assemblyName); - return Assembly.LoadFrom(path); + Logger.Log(LogLevel.Debug, "AssemblyResolve: {0} not found in profiler directory, returning null", assemblyName); + return null; } - return null; + try + { + Logger.Log(LogLevel.Debug, "Loading {0} assembly from {1}", assemblyName, path); + var assembly = Assembly.LoadFrom(path); + Logger.Log(LogLevel.Debug, "Loaded {0} from {1}", assemblyName, assembly.Location); + return assembly; + } + catch (Exception e) + { + Logger.Log(LogLevel.Error, e, "AssemblyResolve: failed to load {0} from {1}", assemblyName, path); + return null; + } } } } diff --git a/src/profiler/Elastic.Apm.Profiler.Managed.Loader/Startup.cs b/src/profiler/Elastic.Apm.Profiler.Managed.Loader/Startup.cs index 1c1e47713..64f14c152 100644 --- a/src/profiler/Elastic.Apm.Profiler.Managed.Loader/Startup.cs +++ b/src/profiler/Elastic.Apm.Profiler.Managed.Loader/Startup.cs @@ -16,12 +16,18 @@ public partial class Startup { static Startup() { - Logger.Log(LogLevel.Information, "Elastic.Apm.Profiler.Managed.Loader.Startup: Invoked "); + Logger.Log(LogLevel.Information, "Elastic.Apm.Profiler.Managed.Loader.Startup: Invoked. AppDomain: {0}, CLR version: {1}", + AppDomain.CurrentDomain.FriendlyName, Environment.Version); + var loaderOptimization = ReadEnvironmentVariable("COMPlus_LoaderOptimization"); + Logger.Log(LogLevel.Debug, "COMPlus_LoaderOptimization={0}", loaderOptimization ?? "(not set)"); + Logger.Log(LogLevel.Debug, "AppDomain base directory: {0}", AppDomain.CurrentDomain.BaseDirectory); + Logger.Log(LogLevel.Debug, "AppDomain shadow copy files: {0}", AppDomain.CurrentDomain.ShadowCopyFiles); Directory = ResolveDirectory(); try { AppDomain.CurrentDomain.AssemblyResolve += ResolveDependencies; + Logger.Log(LogLevel.Debug, "AssemblyResolve event handler registered on AppDomain '{0}'", AppDomain.CurrentDomain.FriendlyName); } catch (Exception e) { @@ -36,13 +42,76 @@ private static void TryLoadManagedAssembly() try { var version = Assembly.GetExecutingAssembly().GetName().Version; - var assembly = Assembly.Load($"Elastic.Apm.Profiler.Managed, Version={version}, Culture=neutral, PublicKeyToken=ae7400d2c189cf22"); + var assemblyName = $"Elastic.Apm.Profiler.Managed, Version={version}, Culture=neutral, PublicKeyToken=ae7400d2c189cf22"; + + Assembly assembly; + try + { + var alreadyLoaded = Array.FindAll( + AppDomain.CurrentDomain.GetAssemblies(), + a => string.Equals(a.GetName().Name, "Elastic.Apm.Profiler.Managed", StringComparison.OrdinalIgnoreCase)); + if (alreadyLoaded.Length > 0) + { + foreach (var loaded in alreadyLoaded) + Logger.Log(LogLevel.Warning, "Elastic.Apm.Profiler.Managed already loaded in AppDomain before Assembly.Load: {0} from '{1}'", loaded.FullName, loaded.Location); + } + else + Logger.Log(LogLevel.Debug, "Elastic.Apm.Profiler.Managed not yet present in AppDomain"); + + Logger.Log(LogLevel.Debug, "Attempting Assembly.Load for {0}", assemblyName); + assembly = Assembly.Load(assemblyName); + Logger.Log(LogLevel.Debug, "Assembly.Load succeeded: {0}", assembly?.Location ?? "(null)"); + } + catch (Exception loadEx) + { + // Assembly.Load can fail on .NET Framework when the CLR's fusion probing finds the + // assembly in a path outside the profiler folder (e.g. the application's bin directory + // from a previous shadow-copy or partial bind) but cannot satisfy all its dependencies + // from that location. In that case AssemblyResolve is never fired. Fall back to + // Assembly.LoadFrom with the explicit profiler path, which bypasses fusion probing. + WarnIfConflictingAssemblyInAppPath("Elastic.Apm.Profiler.Managed.dll"); + Logger.Log(LogLevel.Warning, loadEx, "Assembly.Load failed for {0}, falling back to Assembly.LoadFrom from {1}", assemblyName, Directory); + var path = System.IO.Path.Combine(Directory, "Elastic.Apm.Profiler.Managed.dll"); + Logger.Log(LogLevel.Debug, "Assembly.LoadFrom path: {0}, exists: {1}", path, System.IO.File.Exists(path)); + assembly = Assembly.LoadFrom(path); + Logger.Log(LogLevel.Debug, "Assembly.LoadFrom succeeded: {0}", assembly?.Location ?? "(null)"); + Logger.Log(LogLevel.Warning, + "Assembly loaded via LoadFrom fallback (Load context unavailable). " + + "Native profiler ReJIT instrumentation may not activate. " + + "If instrumentation is missing, set COMPlus_LoaderOptimization=1 on the app pool environment variables."); + } + if (assembly == null) + { + Logger.Log(LogLevel.Error, "Failed to load Elastic.Apm.Profiler.Managed: assembly is null"); return; + } + + if (!string.IsNullOrEmpty(assembly.Location) + && !assembly.Location.StartsWith(Directory, StringComparison.OrdinalIgnoreCase)) + { + Logger.Log(LogLevel.Warning, + "Elastic.Apm.Profiler.Managed loaded from unexpected location: {0}. Expected location under profiler directory: {1}. This may indicate a version mismatch.", + assembly.Location, Directory); + } var type = assembly.GetType("Elastic.Apm.Profiler.Managed.AutoInstrumentation", throwOnError: false); - var method = type?.GetRuntimeMethod("Initialize", parameters: Type.EmptyTypes); - method?.Invoke(obj: null, parameters: null); + if (type == null) + { + Logger.Log(LogLevel.Error, "Could not find type Elastic.Apm.Profiler.Managed.AutoInstrumentation in {0}", assembly.Location); + return; + } + + var method = type.GetRuntimeMethod("Initialize", parameters: Type.EmptyTypes); + if (method == null) + { + Logger.Log(LogLevel.Error, "Could not find method AutoInstrumentation.Initialize in {0}", assembly.Location); + return; + } + + Logger.Log(LogLevel.Debug, "Invoking AutoInstrumentation.Initialize"); + method.Invoke(obj: null, parameters: null); + Logger.Log(LogLevel.Information, "AutoInstrumentation.Initialize completed successfully"); } catch (Exception e) { @@ -52,6 +121,27 @@ private static void TryLoadManagedAssembly() internal static string Directory { get; } + private static void WarnIfConflictingAssemblyInAppPath(string fileName) + { + var baseDir = AppDomain.CurrentDomain.BaseDirectory; + var candidates = new[] + { + System.IO.Path.Combine(baseDir, fileName), + System.IO.Path.Combine(baseDir, "bin", fileName), + }; + foreach (var candidate in candidates) + { + if (System.IO.File.Exists(candidate)) + { + Logger.Log(LogLevel.Warning, + "Conflicting assembly found at {0}. Under MultiDomainHost loader optimization (IIS default), " + + "this causes Assembly.Load to fail without firing AssemblyResolve. " + + "Set COMPlus_LoaderOptimization=1 on the app pool environment variables to resolve.", + candidate); + } + } + } + internal static string ReadEnvironmentVariable(string key) { try diff --git a/src/profiler/Elastic.Apm.Profiler.Managed/AutoInstrumentation.cs b/src/profiler/Elastic.Apm.Profiler.Managed/AutoInstrumentation.cs index 46efcbe99..3f8eb58e9 100644 --- a/src/profiler/Elastic.Apm.Profiler.Managed/AutoInstrumentation.cs +++ b/src/profiler/Elastic.Apm.Profiler.Managed/AutoInstrumentation.cs @@ -43,10 +43,17 @@ public static void Initialize() // was instantiated here. // ReSharper disable once ConvertIfToOrExpression if (System.Web.Hosting.HostingEnvironment.IsHosted) + { + Logger.Log(LogLevel.Debug, + "IIS hosted application detected (HostingEnvironment.IsHosted=true) — skipping agent instantiation. " + + "The agent will be configured by ElasticApmModule; native profiler ReJIT hooks will provide SQL/HTTP instrumentation. " + + "Application: {0}", + System.Web.Hosting.HostingEnvironment.ApplicationVirtualPath ?? "(unknown)"); skipInstantiation = true; + } #endif Logger.Log(LogLevel.Debug, - "{0}: value of {1}", $"{nameof(AutoInstrumentation)}.{nameof(Initialize)}", skipInstantiation); + "{0}: skipInstantiation={1}", $"{nameof(AutoInstrumentation)}.{nameof(Initialize)}", skipInstantiation); // ensure global instance is created if it's not already if (!skipInstantiation) diff --git a/test/Elastic.Apm.Tests/Config/GlobalLogConfigurationTests.cs b/test/Elastic.Apm.Tests/Config/GlobalLogConfigurationTests.cs index 63cf310f9..41da118b4 100644 --- a/test/Elastic.Apm.Tests/Config/GlobalLogConfigurationTests.cs +++ b/test/Elastic.Apm.Tests/Config/GlobalLogConfigurationTests.cs @@ -3,6 +3,7 @@ // See the LICENSE file in the project root for more information using System.Collections; +using System.Text.RegularExpressions; using Elastic.Apm.Config; using Elastic.Apm.Logging; using FluentAssertions; @@ -25,6 +26,16 @@ public void Check_Defaults() config.LogTargets.Should().Be(GlobalLogTarget.None); } + [Fact] + public void Check_LogFilePath_ContainsAppDomainIdAndTimestamp() + { + var config = GlobalLogConfiguration.FromEnvironment(new Hashtable()); + var fileName = System.IO.Path.GetFileName(config.AgentLogFilePath); + // Expected format: {processName}_{pid}_ad{appDomainId}_{yyyyMMddTHHmmssfff}.agent.log + Regex.IsMatch(fileName, @"^.+_\d+_ad\d+_\d{8}T\d{9}\.agent\.log$").Should().BeTrue( + "filename '{0}' should match {{processName}}_{{pid}}_ad{{appDomainId}}_{{yyyyMMddTHHmmssfff}}.agent.log", fileName); + } + // [Theory]