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 
…2242)
  • Loading branch information
@Mpdreamz
Mpdreamz authored Dec 18, 2023
1 parent bb8f492 commit 038ece7
Show file tree
Hide file tree
Showing 5 changed files with 217 additions and 143 deletions.
278 changes: 150 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,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<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;
}
}
}
}
46 changes: 33 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,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<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 038ece7

Please sign in to comment.