Skip to content

Commit

Permalink
Move logging caching over to ConditionalWeaktable as fix for #2234
Browse files Browse the repository at this point in the history 
This also ensure we no longer use captures state in lambda's by moving the logging
callback to static to disable capturing state.
  • Loading branch information
@Mpdreamz
Mpdreamz committed Dec 13, 2023
1 parent ebd4be9 commit 8cc365f
Show file tree
Hide file tree
Showing 4 changed files with 211 additions and 143 deletions.
276 changes: 148 additions & 128 deletions src/Elastic.Apm/Logging/IApmLoggingExtensions.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3,157 +3,177 @@
// 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<string, LogValuesFormatter> 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<string, LogValuesFormatter> Formatters { get; } = new ConcurrentDictionary<string, LogValuesFormatter>();
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

/// <summary>
/// Depending on the two parameters it either returns a MaybeLogger instance or null.
/// </summary>
/// <param name="logger">The logger you want to log with</param>
/// <param name="level">The level to compare with</param>
/// <returns>If the return value is not null you can call <see cref="MaybeLogger.Log" /> to log</returns>
internal static MaybeLogger? IfLevel(this IApmLogger logger, LogLevel level) =>
logger.IsEnabled(level) ? new MaybeLogger(logger, level) : (MaybeLogger?)null;

/// <summary>
/// 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.
/// </summary>
/// <param name="logger">The logger instance you want to log with</param>
/// <returns>Either a MaybeLogger or null</returns>
internal static MaybeLogger? Trace(this IApmLogger logger) => IfLevel(logger, LogLevel.Trace);

/// <summary>
/// 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.
/// </summary>
/// <param name="logger">The logger instance you want to log with</param>
/// <returns>Either a MaybeLogger or null</returns>
internal static MaybeLogger? Debug(this IApmLogger logger) => IfLevel(logger, LogLevel.Debug);

/// <summary>
/// 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.
/// </summary>
/// <param name="logger">The logger instance you want to log with</param>
/// <returns>Either a MaybeLogger or null</returns>
internal static MaybeLogger? Info(this IApmLogger logger) => IfLevel(logger, LogLevel.Information);

/// <summary>
/// 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.
/// </summary>
/// <param name="logger">The logger instance you want to log with</param>
/// <returns>Either a MaybeLogger or null</returns>
internal static MaybeLogger? Warning(this IApmLogger logger) => IfLevel(logger, LogLevel.Warning);

/// <summary>
/// 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.
/// </summary>
/// <param name="logger">The logger instance you want to log with</param>
/// <returns>Either a MaybeLogger or null</returns>
internal static MaybeLogger? Error(this IApmLogger logger) => IfLevel(logger, LogLevel.Error);

/// <summary>
/// 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.
/// </summary>
/// <param name="logger">The logger instance you want to log with</param>
/// <returns>Either a MaybeLogger or null</returns>
internal static MaybeLogger? Critical(this IApmLogger logger) => IfLevel(logger, LogLevel.Critical);

internal readonly struct MaybeLogger
private static LogValuesFormatter GetOrAddFormatter(string message, IReadOnlyCollection<object> 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
}

/// <summary>
/// Depending on the two parameters it either returns a MaybeLogger instance or null.
/// </summary>
/// <param name="logger">The logger you want to log with</param>
/// <param name="level">The level to compare with</param>
/// <returns>If the return value is not null you can call <see cref="MaybeLogger.Log" /> to log</returns>
internal static MaybeLogger? IfLevel(this IApmLogger logger, LogLevel level) =>
logger.IsEnabled(level) ? new MaybeLogger(logger, level) : (MaybeLogger?)null;

/// <summary>
/// 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.
/// </summary>
/// <param name="logger">The logger instance you want to log with</param>
/// <returns>Either a MaybeLogger or null</returns>
internal static MaybeLogger? Trace(this IApmLogger logger) => IfLevel(logger, LogLevel.Trace);

/// <summary>
/// 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.
/// </summary>
/// <param name="logger">The logger instance you want to log with</param>
/// <returns>Either a MaybeLogger or null</returns>
internal static MaybeLogger? Debug(this IApmLogger logger) => IfLevel(logger, LogLevel.Debug);

/// <summary>
/// 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.
/// </summary>
/// <param name="logger">The logger instance you want to log with</param>
/// <returns>Either a MaybeLogger or null</returns>
internal static MaybeLogger? Info(this IApmLogger logger) => IfLevel(logger, LogLevel.Information);

/// <summary>
/// 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.
/// </summary>
/// <param name="logger">The logger instance you want to log with</param>
/// <returns>Either a MaybeLogger or null</returns>
internal static MaybeLogger? Warning(this IApmLogger logger) => IfLevel(logger, LogLevel.Warning);

/// <summary>
/// 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.
/// </summary>
/// <param name="logger">The logger instance you want to log with</param>
/// <returns>Either a MaybeLogger or null</returns>
internal static MaybeLogger? Error(this IApmLogger logger) => IfLevel(logger, LogLevel.Error);

/// <summary>
/// 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.
/// </summary>
/// <param name="logger">The logger instance you want to log with</param>
/// <returns>Either a MaybeLogger or null</returns>
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);
}
}
}
12 changes: 10 additions & 2 deletions src/Elastic.Apm/Logging/LogValuesFormatter.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -195,12 +195,20 @@ public LogValues GetState(object[] values)
args[offset + i] = new KeyValuePair<string, object>(ValueNames[j], values[i]);
}

return new LogValues(args);
return new LogValues(this, values, args);
}

public class LogValues : ReadOnlyCollection<KeyValuePair<string, object>>
{
public LogValues(IList<KeyValuePair<string, object>> list) : base(list) { }
internal LogValuesFormatter Formatter { get; }
internal object[] Args { get; }

public LogValues(LogValuesFormatter formatter, object[] args, IList<KeyValuePair<string, object>> list)
: base(list)
{
Formatter = formatter;
Args = args;
}
}
}
}
44 changes: 31 additions & 13 deletions src/Elastic.Apm/Logging/ScopedLogger.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3,27 +3,45 @@
// 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<string, LogValuesFormatter> Formatters { get; } = new ConcurrentDictionary<string, LogValuesFormatter>();
internal ConditionalWeakTable<string, LogValuesFormatter> 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<object> args)
=> Formatters.GetOrAdd(message, s => new LogValuesFormatter($"{{{{{{Scope}}}}}} {s}", args, Scope));
public bool IsEnabled(LogLevel level) => Logger.IsEnabled(level);

void IApmLogger.Log<TState>(LogLevel level, TState state, Exception e, Func<TState, Exception, string> formatter) =>
Logger.Log(level, state, e, formatter);
internal LogValuesFormatter GetOrAddFormatter(string message, IReadOnlyCollection<object> 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<TState>(LogLevel level, TState state, Exception e, Func<TState, Exception, string> formatter) =>
Logger.Log(level, state, e, formatter);
}
Loading

0 comments on commit 8cc365f

Please sign in to comment.