Use TraceLogger as default logger in ASP.NET Full Framework (#1288)

This commit adds a logger implementation, TraceLogger, that
writes agent logs to a TraceSource with name "Elastic.Apm".
This logger is configured as the default logger for
ASP.NET Full Framework applications, which can use configuration
to write log messages to file, debug window, Windows event log, etc.

Add a section to docs with an example of how to configure
the logger in web.config.

Move the default log level from ConsoleLogger into DefaultValues.

Closes #1263

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,6 +6,7 @@
 using System.Collections;
 using System.Collections.Generic;
 using System.Collections.Specialized;
+using System.Configuration;
 using System.Linq;
 using System.Security.Claims;
 using System.Web;
@@ -422,12 +423,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);