Use TraceLogger as default logger in ASP.NET Full Framework

docs/troubleshooting.asciidoc

@@ -46,15 +46,55 @@ This means the Agent will pick up the configured logging provider and log as any
 [[collect-logs-classic]]
 ==== ASP.NET Classic
 
-Unlike ASP.NET Core, ASP.NET (classic) does not have a predefined logging system.
-However, if you have a logging system in place, like NLog, Serilog, or similar, you can direct the agent logs into your
-logging system by creating a bridge between the agent's internal logger and your logging system.
+ASP.NET (classic) does not have a predefined logging system. By default, the agent is configured to
+emit log messages to a 
+https://docs.microsoft.com/en-us/dotnet/api/system.diagnostics.tracesource[`System.Diagnostics.TraceSource`] 
+with the source name `"Elastic.Apm"`. The TraceSource adheres to the log levels defined in the
+APM agent configuration.
+
+[IMPORTANT]
+--
+System.Diagnostics.TraceSource requires the https://docs.microsoft.com/en-us/dotnet/framework/debug-trace-profile/how-to-compile-conditionally-with-trace-and-debug[`TRACE` compiler directive to be specified], which is specified
+by default for both Debug and Release build configurations.
+--
+
+https://docs.microsoft.com/en-us/dotnet/api/system.diagnostics.tracelistener[TraceListeners]
+can be configured to monitor log messages for the trace source, using the https://docs.microsoft.com/en-us/dotnet/framework/configure-apps/file-schema/trace-debug/system-diagnostics-element[`<system.diagnostics>`] section of
+web.config. For example, the following web.config section writes Elastic.Apm log messages to a file
+named my_log_file.log:
+
+[source,xml]
+----
+<configuration>
+  <!-- other sections .... -->
+<system.diagnostics>
+	<sources>
+		<source name="Elastic.Apm"> <1>
+			<listeners>
+				<add name="file" 
+					type="System.Diagnostics.TextWriterTraceListener" 
+					initializeData="my_log_file.log" />
+			</listeners>
+		</source>
+	</sources>
+</system.diagnostics>
+</configuration>  
+----
+<1> Define listeners under a source with name `"Elastic.Apm"` to capture agent logs
+
+[float]
+[[collect-logs-class-other-logging-systems]]
+===== Other logging systems
+
+If you have a logging system in place such as https://nlog-project.org/[NLog], https://serilog.net/[Serilog], 
+or similar, you can direct the agent logs into your logging system by creating an adapter between 
+the agent's internal logger and your logging system.
 
 First implement the `IApmLogger` interface from the `Elastic.Apm.Logging` namespace:
 
 [source,csharp]
 ----
-internal class ApmLoggerBridge : IApmLogger
+internal class ApmLoggerAdapter : IApmLogger
 {
 	private readonly Lazy<Logger> _logger;
 	public bool IsEnabled(ApmLogLevel level)
@@ -71,31 +111,44 @@ internal class ApmLoggerBridge : IApmLogger
 }
 ----
 
-An example implementation for NLog can be seen https://github.com/elastic/apm-agent-dotnet/blob/master/sample/AspNetFullFrameworkSampleApp/App_Start/ApmLoggerToNLog.cs[in our GitHub repository].
-
-Then tell the agent to use the `ApmLoggerBridge`.
+An example implementation for NLog can be seen https://github.com/elastic/apm-agent-dotnet/blob/f6a33a185675b7b918af59d3333d94b32329a84a/sample/AspNetFullFrameworkSampleApp/App_Start/ApmLoggerToNLog.cs[in our GitHub repository].
 
-For this in ASP.NET (classic) you need to place the following code into the `Application_Start` method in the `HttpApplication` implementation of your app which is typically in the `Global.asx.cs` file:
+Then tell the agent to use the `ApmLoggerAdapter`. For ASP.NET (classic), place the following code into the `Application_Start` 
+method in the `HttpApplication` implementation of your app which is typically in the `Global.asax.cs` file:
 
 [source,csharp]
 ----
-AgentDependencies.Logger = new ApmLoggerBridge();
+using Elastic.Apm.AspNetFullFramework;
+
+namespace MyApp
+{
+	public class MyApplication : HttpApplication
+	{
+		protected void Application_Start()
+		{
+			AgentDependencies.Logger = new ApmLoggerAdapter();
+
+			// other application setup...
+		}
+	}
+}
 ----
 
-The `AgentDependencies` class lives in the `Elastic.Apm.AspNetFullFramework` namespace.
-During initialization, the agent checks if an additional logger was configured--the agent only does this once, so it's important to set it as early in the process as possible (typically in the `Application_Start` method).
+During initialization, the agent checks if an additional logger was configured-- the agent only does this once, so it's important 
+to set it as early in the process as possible, typically in the `Application_Start` method.
 
 [float]
 [[collect-logs-general]]
 ==== General .NET applications
 
-If none of the above cases apply to your application, you can still use a bridge and redirect agent logs into a .NET logging system (like NLog, Serilog, or similar).
+If none of the above cases apply to your application, you can still use a logger adapter and redirect agent logs into a .NET 
+logging system like NLog, Serilog, or similar.
 
 For this you'll need an `IApmLogger` implementation (see above) which you need to pass to the `Setup` method during agent setup:
 
 [source,csharp]
 ----
-Agent.Setup(new AgentComponents(logger: new ApmLoggerBridge()));
+Agent.Setup(new AgentComponents(logger: new ApmLoggerAdapter()));
 ----
 
 [float]

sample/AspNetFullFrameworkSampleApp/App_Start/LoggingConfig.cs

@@ -26,8 +26,6 @@ public class LoggingConfig
 
 		public static void SetupLogging()
 		{
-			var logFileEnvVarValue = Environment.GetEnvironmentVariable(LogFileEnvVarName);
-
 			var config = new LoggingConfiguration();
 			const string layout = "${date:format=yyyy-MM-dd HH\\:mm\\:ss.fff zzz}" +
 				" | ${level:uppercase=true:padding=-5}" + // negative values cause right padding
@@ -41,6 +39,7 @@ public static void SetupLogging()
 				new PrefixingTraceTarget($"Elastic APM .NET {nameof(AspNetFullFrameworkSampleApp)}> "), LogMemoryTarget, new ConsoleTarget()
 			};
 
+			var logFileEnvVarValue = Environment.GetEnvironmentVariable(LogFileEnvVarName);
 			if (logFileEnvVarValue != null) logTargets.Add(new FileTarget { FileName = logFileEnvVarValue, DeleteOldFileOnStartup = true });
 
 			foreach (var logTarget in logTargets) logTarget.Layout = layout;

sample/AspNetFullFrameworkSampleApp/Global.asax.cs

@@ -14,21 +14,21 @@
 using System.Web.Routing;
 using AspNetFullFrameworkSampleApp.Mvc;
 using Elastic.Apm;
-using NLog;
-
+using NLog;
+
 namespace AspNetFullFrameworkSampleApp
 {
 	public class MvcApplication : HttpApplication
 	{
 		protected void Application_Start()
-		{
-			LoggingConfig.SetupLogging();
-
-			var logger = LogManager.GetCurrentClassLogger();
-			logger.Info("Current process ID: {ProcessID}, ELASTIC_APM_SERVER_URLS: {ELASTIC_APM_SERVER_URLS}",
-				Process.GetCurrentProcess().Id, Environment.GetEnvironmentVariable("ELASTIC_APM_SERVER_URLS"));
-
-			// Web API setup
+		{
+			LoggingConfig.SetupLogging();
+
+			var logger = LogManager.GetCurrentClassLogger();
+			logger.Info("Current process ID: {ProcessID}, ELASTIC_APM_SERVER_URLS: {ELASTIC_APM_SERVER_URLS}",
+				Process.GetCurrentProcess().Id, Environment.GetEnvironmentVariable("ELASTIC_APM_SERVER_URLS"));
+
+			// Web API setup
 			HttpBatchHandler batchHandler = new DefaultHttpBatchHandler(GlobalConfiguration.DefaultServer)
 			{
 				ExecutionOrder = BatchExecutionOrder.NonSequential

src/Elastic.Apm.AspNetFullFramework/ElasticApmModule.cs

@@ -6,12 +6,14 @@
 using System.Collections;
 using System.Collections.Generic;
 using System.Collections.Specialized;
+using System.Configuration;
 using System.Linq;
 using System.Security.Claims;
 using System.Web;
 using Elastic.Apm.Api;
 using Elastic.Apm.AspNetFullFramework.Extensions;
 using Elastic.Apm.AspNetFullFramework.Helper;
+using Elastic.Apm.Config;
 using Elastic.Apm.DiagnosticSource;
 using Elastic.Apm.Helpers;
 using Elastic.Apm.Logging;
@@ -416,12 +418,22 @@ private static bool InitOnceForAllInstancesUnderLock(string dbgInstanceName) =>
 				Agent.Instance.Subscribe(new HttpDiagnosticsSubscriber());
 			}) ?? false;
 
-		private static IApmLogger BuildLogger() => AgentDependencies.Logger ?? ConsoleLogger.Instance;
+		private static IApmLogger CreateDefaultLogger()
+		{
+			var logLevel = ConfigurationManager.AppSettings[ConfigConsts.KeyNames.LogLevel];
+			if (string.IsNullOrEmpty(logLevel))
+				logLevel = Environment.GetEnvironmentVariable(ConfigConsts.EnvVarNames.LogLevel);
+
+			var level = ConfigConsts.DefaultValues.LogLevel;
+			if (!string.IsNullOrEmpty(logLevel))
+				Enum.TryParse(logLevel, true, out level);
+
+			return new TraceLogger(level);
+		}
 
 		private static AgentComponents CreateAgentComponents(string dbgInstanceName)
 		{
-			var rootLogger = BuildLogger();
-
+			var rootLogger = AgentDependencies.Logger ?? CreateDefaultLogger();
 			var reader = ConfigHelper.CreateReader(rootLogger) ?? new FullFrameworkConfigReader(rootLogger);
 			var agentComponents = new FullFrameworkAgentComponents(rootLogger, reader);
 

src/Elastic.Apm/Config/AbstractConfigurationReader.cs

@@ -213,15 +213,15 @@ protected LogLevel ParseLogLevel(ConfigurationKeyValue kv)
 			if (TryParseLogLevel(kv?.Value, out var level)) return level;
 
 			if (kv?.Value == null)
-				_logger?.Debug()?.Log("No log level provided. Defaulting to log level '{DefaultLogLevel}'", ConsoleLogger.DefaultLogLevel);
+				_logger?.Debug()?.Log("No log level provided. Defaulting to log level '{DefaultLogLevel}'", DefaultValues.LogLevel);
 			else
 			{
 				_logger?.Error()
 					?.Log("Failed parsing log level from {Origin}: {Key}, value: {Value}. Defaulting to log level '{DefaultLogLevel}'",
-						kv.ReadFrom, kv.Key, kv.Value, ConsoleLogger.DefaultLogLevel);
+						kv.ReadFrom, kv.Key, kv.Value, DefaultValues.LogLevel);
 			}
 
-			return ConsoleLogger.DefaultLogLevel;
+			return DefaultValues.LogLevel;
 		}
 
 		protected Uri ParseServerUrl(ConfigurationKeyValue kv) =>

src/Elastic.Apm/Config/ConfigConsts.cs

@@ -6,6 +6,7 @@
 using System.Collections.Generic;
 using Elastic.Apm.Cloud;
 using Elastic.Apm.Helpers;
+using Elastic.Apm.Logging;
 
 namespace Elastic.Apm.Config
 {
@@ -25,6 +26,7 @@ public static class DefaultValues
 			public const bool CentralConfig = true;
 			public const string CloudProvider = SupportedValues.CloudProviderAuto;
 			public const int FlushIntervalInMilliseconds = 10_000; // 10 seconds
+			public const LogLevel LogLevel = Logging.LogLevel.Error;
 			public const int MaxBatchEventCount = 10;
 			public const int MaxQueueEventCount = 1000;
 			public const string MetricsInterval = "30s";

src/Elastic.Apm/Logging/ConsoleLogger.cs

@@ -4,13 +4,14 @@
 
 using System;
 using System.IO;
+using Elastic.Apm.Config;
+using static Elastic.Apm.Config.ConfigConsts;
 
 namespace Elastic.Apm.Logging
 {
 	internal class ConsoleLogger : IApmLogger, ILogLevelSwitchable
 	{
 		private static readonly object SyncRoot = new object();
-		internal static readonly LogLevel DefaultLogLevel = LogLevel.Error;
 
 		private readonly TextWriter _errorOut;
 		private readonly TextWriter _standardOut;
@@ -22,15 +23,15 @@ public ConsoleLogger(LogLevel level, TextWriter standardOut = null, TextWriter e
 			_errorOut = errorOut ?? Console.Error;
 		}
 
-		public static ConsoleLogger Instance { get; } = new ConsoleLogger(DefaultLogLevel);
+		public static ConsoleLogger Instance { get; } = new ConsoleLogger(DefaultValues.LogLevel);
 
 		public LogLevelSwitch LogLevelSwitch { get; }
 
 		private LogLevel Level => LogLevelSwitch.Level;
 
 		public static ConsoleLogger LoggerOrDefault(LogLevel? level)
 		{
-			if (level.HasValue && level.Value != DefaultLogLevel)
+			if (level.HasValue && level.Value != DefaultValues.LogLevel)
 				return new ConsoleLogger(level.Value);
 
 			return Instance;

src/Elastic.Apm/Logging/TraceLogger.cs

@@ -0,0 +1,101 @@
+// Licensed to Elasticsearch B.V under
+// one or more agreements.
+// Elasticsearch B.V licenses this file to you under the Apache 2.0 License.
+// See the LICENSE file in the project root for more information
+
+using System;
+using System.Diagnostics;
+using System.Runtime.CompilerServices;
+using System.Text;
+using Elastic.Apm.Helpers;
+
+namespace Elastic.Apm.Logging
+{
+	/// <summary>
+	/// A logging implementation that logs to a <see cref="TraceSource"/> with the source name <c>Elastic.Apm</c>
+	/// </summary>
+	internal class TraceLogger : IApmLogger, ILogLevelSwitchable
+	{
+		private const string SourceName = "Elastic.Apm";
+
+		private static readonly TraceSource TraceSource;
+
+		static TraceLogger() => TraceSource = new TraceSource(SourceName);
+
+		public TraceLogger(LogLevel level) => LogLevelSwitch = new LogLevelSwitch(level);
+
+		public LogLevelSwitch LogLevelSwitch { get; }
+
+		private LogLevel Level => LogLevelSwitch.Level;
+
+		public bool IsEnabled(LogLevel level) => Level <= level;
+
+		public void Log<TState>(LogLevel level, TState state, Exception e, Func<TState, Exception, string> formatter)
+		{
+			if (!IsEnabled(level)) return;
+
+			var message = formatter(state, e);
+			var logLevel = LevelToString(level);
+
+			StringBuilder builder;
+			string exceptionType = null;
+			var capacity = 51 + message.Length + logLevel.Length;
+
+			if (e is null)
+				builder = new StringBuilder(capacity);
+			else
+			{
+				exceptionType = e.GetType().FullName;
+				builder = new StringBuilder(capacity + exceptionType.Length + e.Message.Length + e.StackTrace.Length);
+			}
+
+			builder.Append('[')
+				.Append(DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss.fff zzz"))
+				.Append("][")
+				.Append(logLevel)
+				.Append("] - ")
+				.Append(message);
+
+			if (e != null)
+			{
+				builder.Append("+-> Exception: ")
+					.Append(exceptionType)
+					.Append(": ")
+					.AppendLine(e.Message)
+					.AppendLine(e.StackTrace);
+			}
+
+			var logMessage = builder.ToString();
+			for (var i = 0; i < TraceSource.Listeners.Count; i++)
+			{
+				var listener = TraceSource.Listeners[i];
+				if (!listener.IsThreadSafe)
+				{
+					lock (listener)
+						listener.WriteLine(logMessage);
+				}
+				else
+					listener.WriteLine(logMessage);
+			}
+
+			TraceSource.Flush();
+		}
+
+		[MethodImpl(MethodImplOptions.AggressiveInlining)]
+		internal static string LevelToString(LogLevel level)
+		{
+			switch (level)
+			{
+				case LogLevel.Error: return "Error";
+				case LogLevel.Warning: return "Warning";
+				case LogLevel.Information: return "Info";
+				case LogLevel.Debug: return "Debug";
+				case LogLevel.Trace: return "Trace";
+				case LogLevel.Critical: return "Critical";
+				// ReSharper disable once RedundantCaseLabel
+				case LogLevel.None:
+				default: return "None";
+			}
+		}
+	}
+}

test/Elastic.Apm.AspNetFullFramework.Tests/HttpContextCurrentExecutionSegmentsContainerTests.cs

@@ -38,9 +38,8 @@ public async Task Transaction_And_Spans_Captured_When_Large_Request()
 			bytes.Should().BeGreaterThan(20_000);
 			var content = new StringContent(json, Encoding.UTF8, "application/json");
 
-			var client = new HttpClient();
 			var bulkSamplesUri = Consts.SampleApp.CreateUrl("/Database/Bulk");
-			var response = await client.PostAsync(bulkSamplesUri, content).ConfigureAwait(false);
+			var response = await HttpClient.PostAsync(bulkSamplesUri, content).ConfigureAwait(false);
 
 			var responseContent = await response.Content.ReadAsStringAsync();
 			response.IsSuccessStatusCode.Should().BeTrue(responseContent);
@@ -62,9 +61,8 @@ public async Task Transaction_And_Spans_Captured_When_Controller_Action_Makes_As
 			var count = 100;
 			var content = new StringContent($"{{\"count\":{count}}}", Encoding.UTF8, "application/json");
 
-			var client = new HttpClient();
 			var bulkSamplesUri = Consts.SampleApp.CreateUrl("/Database/Generate");
-			var response = await client.PostAsync(bulkSamplesUri, content).ConfigureAwait(false);
+			var response = await HttpClient.PostAsync(bulkSamplesUri, content).ConfigureAwait(false);
 
 			var responseContent = await response.Content.ReadAsStringAsync();
 			response.IsSuccessStatusCode.Should().BeTrue(responseContent);