diff --git a/src/Elastic.Apm/Logging/IApmLoggingExtensions.cs b/src/Elastic.Apm/Logging/IApmLoggingExtensions.cs index 825e21b30..b645b54ca 100644 --- a/src/Elastic.Apm/Logging/IApmLoggingExtensions.cs +++ b/src/Elastic.Apm/Logging/IApmLoggingExtensions.cs @@ -3,157 +3,179 @@ // See the LICENSE file in the project root for more information using System; -using System.Collections.Concurrent; +using System.Collections.Generic; using System.Diagnostics; using System.IO; using System.Linq; using System.Runtime.CompilerServices; using Elastic.Apm.Helpers; -namespace Elastic.Apm.Logging +namespace Elastic.Apm.Logging; + +internal static class LoggingExtensions { - internal static class LoggingExtensions + private static ConditionalWeakTable Formatters { get; } = new(); + + internal static ScopedLogger Scoped(this IApmLogger logger, string scope) => new(logger is ScopedLogger s ? s.Logger : logger, scope); + + private static void DoLog(this IApmLogger logger, LogLevel level, string message, Exception e, params object[] args) { - private static ConcurrentDictionary Formatters { get; } = new ConcurrentDictionary(); + try + { + var formatter = logger is ScopedLogger sl + ? sl.GetOrAddFormatter(message, args) + : GetOrAddFormatter(message, args); - internal static ScopedLogger Scoped(this IApmLogger logger, string scope) => - new ScopedLogger(logger is ScopedLogger s ? s.Logger : logger, scope); + var logValues = formatter.GetState(args); - private static void DoLog(this IApmLogger logger, LogLevel level, string message, Exception e, params object[] args) + logger?.Log(level, logValues, e, static (l, _) => l.Formatter.Format(l.Args)); + } + catch (Exception exception) { + // For now we will just print it to System.Diagnostics.Trace + // In the future we should consider error counters to increment and log periodically on a worker thread try { - var formatter = logger is ScopedLogger sl - ? sl.GetOrAddFormatter(message, args) - : Formatters.GetOrAdd(message, s => new LogValuesFormatter(s, args)); - - var logValues = formatter.GetState(args); - - logger?.Log(level, logValues, e, (_, _) => formatter.Format(args)); + var newLine = Environment.NewLine + "Elastic APM .NET Agent: "; + var currentStackTraceFrames = new StackTrace(true).GetFrames(); + var currentStackTrace = currentStackTraceFrames == null + ? " N/A" + : newLine + string.Join("", currentStackTraceFrames.Select(f => " " + f)); + + System.Diagnostics.Trace.WriteLine("Elastic APM .NET Agent: [CRITICAL] Exception thrown by logging implementation." + + $" Log message: `{message.AsNullableToString()}'." + + $" args.Length: {args.Length}." + + $" Current thread: {DbgUtils.CurrentThreadDesc}" + + newLine + + $"+-> Exception (exception): {exception.GetType().FullName}: {exception.Message}{newLine}{exception.StackTrace}" + + (e != null + ? newLine + $"+-> Exception (e): {e.GetType().FullName}: {e.Message}{newLine}{e.StackTrace}" + : $"e: {ObjectExtensions.NullAsString}") + + newLine + + "+-> Current stack trace:" + currentStackTrace + ); } - catch (Exception exception) + catch (Exception) { - // For now we will just print it to System.Diagnostics.Trace - // In the future we should consider error counters to increment and log periodically on a worker thread - try - { - var newLine = Environment.NewLine + "Elastic APM .NET Agent: "; - var currentStackTraceFrames = new StackTrace(true).GetFrames(); - var currentStackTrace = currentStackTraceFrames == null - ? " N/A" - : newLine + string.Join("", currentStackTraceFrames.Select(f => " " + f)); - - System.Diagnostics.Trace.WriteLine("Elastic APM .NET Agent: [CRITICAL] Exception thrown by logging implementation." - + $" Log message: `{message.AsNullableToString()}'." - + $" args.Length: {args.Length}." - + $" Current thread: {DbgUtils.CurrentThreadDesc}" - + newLine - + $"+-> Exception (exception): {exception.GetType().FullName}: {exception.Message}{newLine}{exception.StackTrace}" - + (e != null - ? newLine + $"+-> Exception (e): {e.GetType().FullName}: {e.Message}{newLine}{e.StackTrace}" - : $"e: {ObjectExtensions.NullAsString}") - + newLine - + "+-> Current stack trace:" + currentStackTrace - ); - } - catch (Exception) - { - // ignored - } + // ignored } } + } + +#if !NET6_0_OR_GREATER + private static readonly object _lock = new(); +#endif - /// - /// Depending on the two parameters it either returns a MaybeLogger instance or null. - /// - /// The logger you want to log with - /// The level to compare with - /// If the return value is not null you can call to log - internal static MaybeLogger? IfLevel(this IApmLogger logger, LogLevel level) => - logger.IsEnabled(level) ? new MaybeLogger(logger, level) : (MaybeLogger?)null; - - /// - /// If the logger has a loglevel, which is higher than or equal to Trace then it returns a MaybeLogger instance, - /// otherwise it returns null. - /// By using the return value with `?.` you can avoid executing code that is not necessary to execute - /// in case the log won't be printed because the loglevel would not allow it. - /// - /// The logger instance you want to log with - /// Either a MaybeLogger or null - internal static MaybeLogger? Trace(this IApmLogger logger) => IfLevel(logger, LogLevel.Trace); - - /// - /// If the logger has a loglevel, which is higher than or equal to Debug then it returns a MaybeLogger instance, - /// otherwise it returns null. - /// By using the return value with `?.` you can avoid executing code that is not necessary to execute - /// in case the log won't be printed because the loglevel would not allow it. - /// - /// The logger instance you want to log with - /// Either a MaybeLogger or null - internal static MaybeLogger? Debug(this IApmLogger logger) => IfLevel(logger, LogLevel.Debug); - - /// - /// If the logger has a loglevel, which is higher than Info then it returns a MaybeLogger instance, - /// otherwise it returns null. - /// By using the return value with `?.` you can avoid executing code that is not necessary to execute - /// in case the log won't be printed because the loglevel would not allow it. - /// - /// The logger instance you want to log with - /// Either a MaybeLogger or null - internal static MaybeLogger? Info(this IApmLogger logger) => IfLevel(logger, LogLevel.Information); - - /// - /// If the logger has a loglevel, which is higher than or equal to Warning then it returns a MaybeLogger instance, - /// otherwise it returns null. - /// By using the return value with `?.` you can avoid executing code that is not necessary to execute - /// in case the log won't be printed because the loglevel would not allow it. - /// - /// The logger instance you want to log with - /// Either a MaybeLogger or null - internal static MaybeLogger? Warning(this IApmLogger logger) => IfLevel(logger, LogLevel.Warning); - - /// - /// If the logger has a loglevel, which is higher than or equal to Error then it returns a MaybeLogger instance, - /// otherwise it returns null. - /// By using the return value with `?.` you can avoid executing code that is not necessary to execute - /// in case the log won't be printed because the loglevel would not allow it. - /// - /// The logger instance you want to log with - /// Either a MaybeLogger or null - internal static MaybeLogger? Error(this IApmLogger logger) => IfLevel(logger, LogLevel.Error); - - /// - /// If the logger has a loglevel, which is higher than or equal to Critical then it returns a MaybeLogger instance, - /// otherwise it returns null. - /// By using the return value with `?.` you can avoid executing code that is not necessary to execute - /// in case the log won't be printed because the loglevel would not allow it. - /// - /// The logger instance you want to log with - /// Either a MaybeLogger or null - internal static MaybeLogger? Critical(this IApmLogger logger) => IfLevel(logger, LogLevel.Critical); - - internal readonly struct MaybeLogger + private static LogValuesFormatter GetOrAddFormatter(string message, IReadOnlyCollection args) + { + if (Formatters.TryGetValue(message, out var formatter)) + return formatter; + + formatter = new LogValuesFormatter(message, args); +#if NET6_0_OR_GREATER + Formatters.AddOrUpdate(message, formatter); + return formatter; +#else + lock (_lock) { - private readonly IApmLogger _logger; - private readonly LogLevel _level; + if (Formatters.TryGetValue(message, out var f)) + return f; + Formatters.Add(message, formatter); + return formatter; + } +#endif + } + + /// + /// Depending on the two parameters it either returns a MaybeLogger instance or null. + /// + /// The logger you want to log with + /// The level to compare with + /// If the return value is not null you can call to log + internal static MaybeLogger? IfLevel(this IApmLogger logger, LogLevel level) => + logger.IsEnabled(level) ? new MaybeLogger(logger, level) : (MaybeLogger?)null; + + /// + /// If the logger has a loglevel, which is higher than or equal to Trace then it returns a MaybeLogger instance, + /// otherwise it returns null. + /// By using the return value with `?.` you can avoid executing code that is not necessary to execute + /// in case the log won't be printed because the loglevel would not allow it. + /// + /// The logger instance you want to log with + /// Either a MaybeLogger or null + internal static MaybeLogger? Trace(this IApmLogger logger) => IfLevel(logger, LogLevel.Trace); + + /// + /// If the logger has a loglevel, which is higher than or equal to Debug then it returns a MaybeLogger instance, + /// otherwise it returns null. + /// By using the return value with `?.` you can avoid executing code that is not necessary to execute + /// in case the log won't be printed because the loglevel would not allow it. + /// + /// The logger instance you want to log with + /// Either a MaybeLogger or null + internal static MaybeLogger? Debug(this IApmLogger logger) => IfLevel(logger, LogLevel.Debug); + + /// + /// If the logger has a loglevel, which is higher than Info then it returns a MaybeLogger instance, + /// otherwise it returns null. + /// By using the return value with `?.` you can avoid executing code that is not necessary to execute + /// in case the log won't be printed because the loglevel would not allow it. + /// + /// The logger instance you want to log with + /// Either a MaybeLogger or null + internal static MaybeLogger? Info(this IApmLogger logger) => IfLevel(logger, LogLevel.Information); + + /// + /// If the logger has a loglevel, which is higher than or equal to Warning then it returns a MaybeLogger instance, + /// otherwise it returns null. + /// By using the return value with `?.` you can avoid executing code that is not necessary to execute + /// in case the log won't be printed because the loglevel would not allow it. + /// + /// The logger instance you want to log with + /// Either a MaybeLogger or null + internal static MaybeLogger? Warning(this IApmLogger logger) => IfLevel(logger, LogLevel.Warning); + + /// + /// If the logger has a loglevel, which is higher than or equal to Error then it returns a MaybeLogger instance, + /// otherwise it returns null. + /// By using the return value with `?.` you can avoid executing code that is not necessary to execute + /// in case the log won't be printed because the loglevel would not allow it. + /// + /// The logger instance you want to log with + /// Either a MaybeLogger or null + internal static MaybeLogger? Error(this IApmLogger logger) => IfLevel(logger, LogLevel.Error); + + /// + /// If the logger has a loglevel, which is higher than or equal to Critical then it returns a MaybeLogger instance, + /// otherwise it returns null. + /// By using the return value with `?.` you can avoid executing code that is not necessary to execute + /// in case the log won't be printed because the loglevel would not allow it. + /// + /// The logger instance you want to log with + /// Either a MaybeLogger or null + internal static MaybeLogger? Critical(this IApmLogger logger) => IfLevel(logger, LogLevel.Critical); + + internal readonly struct MaybeLogger + { + private readonly IApmLogger _logger; + private readonly LogLevel _level; - public MaybeLogger(IApmLogger logger, LogLevel level) => (_logger, _level) = (logger, level); + public MaybeLogger(IApmLogger logger, LogLevel level) => (_logger, _level) = (logger, level); - public void Log(string message, params object[] args) => _logger.DoLog(_level, message, null, args); + public void Log(string message, params object[] args) => _logger.DoLog(_level, message, null, args); - public void LogException(Exception exception, string message, params object[] args) => - _logger.DoLog(_level, message, exception, args); + public void LogException(Exception exception, string message, params object[] args) => + _logger.DoLog(_level, message, exception, args); - public void LogExceptionWithCaller(Exception exception, - [CallerMemberName] string method = "", - [CallerFilePath] string filePath = "", - [CallerLineNumber] int lineNumber = 0 - ) - { - var file = string.IsNullOrEmpty(filePath) ? string.Empty : new FileInfo(filePath).Name; - _logger?.DoLog(_level, "{ExceptionName} in {Method} ({File}:{LineNumber}): {ExceptionMessage}", exception, - exception?.GetType().Name, method, file, lineNumber, exception?.Message); - } + public void LogExceptionWithCaller(Exception exception, + [CallerMemberName] string method = "", + [CallerFilePath] string filePath = "", + [CallerLineNumber] int lineNumber = 0 + ) + { + var file = string.IsNullOrEmpty(filePath) ? string.Empty : new FileInfo(filePath).Name; + _logger?.DoLog(_level, "{ExceptionName} in {Method} ({File}:{LineNumber}): {ExceptionMessage}", exception, + exception?.GetType().Name, method, file, lineNumber, exception?.Message); } } } diff --git a/src/Elastic.Apm/Logging/LogValuesFormatter.cs b/src/Elastic.Apm/Logging/LogValuesFormatter.cs index 068c5eab9..2f0486630 100644 --- a/src/Elastic.Apm/Logging/LogValuesFormatter.cs +++ b/src/Elastic.Apm/Logging/LogValuesFormatter.cs @@ -195,12 +195,20 @@ public LogValues GetState(object[] values) args[offset + i] = new KeyValuePair(ValueNames[j], values[i]); } - return new LogValues(args); + return new LogValues(this, values, args); } public class LogValues : ReadOnlyCollection> { - public LogValues(IList> list) : base(list) { } + internal LogValuesFormatter Formatter { get; } + internal object[] Args { get; } + + public LogValues(LogValuesFormatter formatter, object[] args, IList> list) + : base(list) + { + Formatter = formatter; + Args = args; + } } } } diff --git a/src/Elastic.Apm/Logging/ScopedLogger.cs b/src/Elastic.Apm/Logging/ScopedLogger.cs index 7c76b12e1..fd01dd417 100644 --- a/src/Elastic.Apm/Logging/ScopedLogger.cs +++ b/src/Elastic.Apm/Logging/ScopedLogger.cs @@ -3,27 +3,47 @@ // See the LICENSE file in the project root for more information using System; -using System.Collections.Concurrent; using System.Collections.Generic; +using System.Runtime.CompilerServices; -namespace Elastic.Apm.Logging +namespace Elastic.Apm.Logging; + +internal class ScopedLogger : IApmLogger { - internal class ScopedLogger : IApmLogger - { - public ScopedLogger(IApmLogger logger, string scope) => (Logger, Scope) = (logger, scope); + public ScopedLogger(IApmLogger logger, string scope) => (Logger, Scope) = (logger, scope); - private ConcurrentDictionary Formatters { get; } = new ConcurrentDictionary(); + internal ConditionalWeakTable Formatters { get; } = new(); - public IApmLogger Logger { get; } + public IApmLogger Logger { get; } - public string Scope { get; } +#if !NET6_0_OR_GREATER + private readonly object _lock = new(); +#endif - public bool IsEnabled(LogLevel level) => Logger.IsEnabled(level); + public string Scope { get; } - internal LogValuesFormatter GetOrAddFormatter(string message, IReadOnlyCollection args) - => Formatters.GetOrAdd(message, s => new LogValuesFormatter($"{{{{{{Scope}}}}}} {s}", args, Scope)); + public bool IsEnabled(LogLevel level) => Logger.IsEnabled(level); - void IApmLogger.Log(LogLevel level, TState state, Exception e, Func formatter) => - Logger.Log(level, state, e, formatter); + internal LogValuesFormatter GetOrAddFormatter(string message, IReadOnlyCollection args) + { + if (Formatters.TryGetValue(message, out var formatter)) + return formatter; + + formatter = new LogValuesFormatter($"{{{{{{Scope}}}}}} {message}", args, Scope); +#if NET6_0_OR_GREATER + Formatters.AddOrUpdate(message, formatter); + return formatter; +#else + lock (_lock) + { + if (Formatters.TryGetValue(message, out var f)) + return f; + Formatters.Add(message, formatter); + return formatter; + } +#endif } + + void IApmLogger.Log(LogLevel level, TState state, Exception e, Func formatter) => + Logger.Log(level, state, e, formatter); } diff --git a/test/Elastic.Apm.Tests/LoggerTests.cs b/test/Elastic.Apm.Tests/LoggerTests.cs index 1f123082d..54c05c334 100644 --- a/test/Elastic.Apm.Tests/LoggerTests.cs +++ b/test/Elastic.Apm.Tests/LoggerTests.cs @@ -145,6 +145,28 @@ public void LogExceptionTest() .ContainAll(new List { "System.Exception", "Something went wrong" }); } + /// + /// Makes sure the logger does not throw in case of templates for structured logs with non-existing corresponding values. + /// This test uses scoped logger. + /// + [Fact] + public void EnsureFormattersAreShared() + { + var consoleLogger = new ConsoleLogger(LogLevel.Trace, TextWriter.Null, TextWriter.Null); + var scopedLogger = consoleLogger.Scoped("MyTestScope"); + for (var i = 0; i < 10; i++) + scopedLogger.Warning()?.Log("This is a test log from the test StructuredLogTemplateWith1MissingArgument, args: {arg1}", i); +#if NET6_0_OR_GREATER + var cachedFormatterCount = scopedLogger.Formatters.Count(); + cachedFormatterCount.Should().Be(1); + + scopedLogger.Warning()?.Log("This is a test log from the test StructuredLogTemplateWith1MissingArgument, args: {arg2}", 2); + cachedFormatterCount = scopedLogger.Formatters.Count(); + cachedFormatterCount.Should().Be(2); +#endif + + } + /// /// Makes sure the logger does not throw in case of templates for structured logs with non-existing corresponding values. /// This test uses scoped logger. diff --git a/test/integrations/Elastic.Apm.AspNetCore.Tests/BaggageAspNetCoreTests.cs b/test/integrations/Elastic.Apm.AspNetCore.Tests/BaggageAspNetCoreTests.cs index 1f431fa77..5ec9bc63d 100644 --- a/test/integrations/Elastic.Apm.AspNetCore.Tests/BaggageAspNetCoreTests.cs +++ b/test/integrations/Elastic.Apm.AspNetCore.Tests/BaggageAspNetCoreTests.cs @@ -36,6 +36,7 @@ public async Task AccessBaggageFromUpstream() (await res.Content.ReadAsStringAsync()).Should().Be("[key1, value1][key2, value2][key3, value3]"); + _payloadSender1.WaitForTransactions(); _payloadSender1.FirstTransaction.IsSampled.Should().BeTrue(); _payloadSender1.FirstTransaction.Context.Request.Headers.Should().ContainKey("baggage"); @@ -67,6 +68,7 @@ public async Task MultipleServices() var res = await client.GetAsync("http://localhost:5901/Home/WriteBaggage"); res.IsSuccessStatusCode.Should().BeTrue(); + _payloadSender1.WaitForTransactions(); _payloadSender1.Transactions.Should().HaveCount(1); // Service 1 has no incoming baggage header and no captured baggage on the transaction