Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Move logging caching over to ConditionalWeaktable as fix for #2234 #2242

Merged
merged 4 commits into from
Dec 18, 2023
Merged

Move logging caching over to ConditionalWeaktable as fix for #2234 #2242

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
8cc365f
Move logging caching over to ConditionalWeaktable as fix for #2234
Mpdreamz Dec 13, 2023
dc462f5
dotnet format
Mpdreamz Dec 13, 2023
4f54f13
ensure waiting for transactions in asp.net core tests
Mpdreamz Dec 13, 2023
657b145
update double lock pattern if statement
Mpdreamz Dec 18, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
278 changes: 150 additions & 128 deletions src/Elastic.Apm/Logging/IApmLoggingExtensions.cs
View file
Open in desktop
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>();
Mpdreamz marked this conversation as resolved.
Show resolved Hide resolved
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
Open in desktop
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
Open in desktop
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
Loading