feat: Add support for Serilog.Extensions.Logging and NLog.Extensions.Logging. (#1860) (#1859)

Author: chynesNR

src/Agent/NewRelic/Agent/Extensions/NewRelic.Agent.Extensions/Logging/LogProviders.cs

@@ -6,21 +6,20 @@
 
 namespace NewRelic.Agent.Extensions.Logging
 {
-    public enum LogProvider
-    {
-        Log4Net,
-        Serilog,
-        NLog
-    }
-
     public static class LogProviders
     {
-        public static readonly bool[] RegisteredLogProvider = new bool[Enum.GetNames(typeof(LogProvider)).Length];
-
-        public static readonly List<string> Log4NetProviderNames = new List<string> { "Microsoft.Extensions.Logging.Log4NetProvider", "log4net.Extensions.Logging.Log4NetProvider" };
-
-        public static readonly List<string> SerilogProviderNames = new List<string> { "Microsoft.Extensions.Logging.SerilogLoggerProvider", "Serilog.Extensions.Logging.SerilogLoggerProvider" };
+        // This will only be set once, when a Microsoft.Extensions.Logging registration method is called.
+        // It can safely be read concurrently.
+        public static bool KnownMELProviderEnabled = false;
 
-        public static readonly List<string> NLogProviderNames = new List<string> { "Microsoft.Extensions.Logging.NLogLoggerProvider", "NLog.Extensions.Logging.NLogLoggerProvider" };
+        public static readonly List<string> KnownMELProviders = new List<string>
+        {
+            "Microsoft.Extensions.Logging.Log4NetProvider",
+            "log4net.Extensions.Logging.Log4NetProvider",
+            "Microsoft.Extensions.Logging.SerilogLoggerProvider",
+            "Serilog.Extensions.Logging.SerilogLoggerProvider",
+            "Microsoft.Extensions.Logging.NLogLoggerProvider",
+            "NLog.Extensions.Logging.NLogLoggerProvider"
+        };
     }
 }

src/Agent/NewRelic/Agent/Extensions/NewRelic.Agent.Extensions/Reflection/VisibilityBypasser.cs

@@ -607,6 +607,18 @@ private static MethodInfo GetMethodInfo(Type type, string methodName)
             return methodInfo;
         }
 
+        public Func<TResult> GenerateParameterlessStaticMethodCaller<TResult>(string assemblyName, string typeName, string methodName)
+        {
+            var ownerType = GetType(assemblyName, typeName);
+
+            var methodInfo = ownerType.GetMethod(methodName, BindingFlags.Public | BindingFlags.NonPublic | BindingFlags.Instance | BindingFlags.Static);
+            if (methodInfo == null)
+            {
+                throw new KeyNotFoundException(string.Format("Unable to find method {0} in type {1}", methodName, ownerType.AssemblyQualifiedName));
+            }
+            return (Func<TResult>)methodInfo.CreateDelegate(typeof(Func<TResult>));
+        }
+
         private static PropertyInfo GetPropertyInfo(Type type, string propertyName)
         {
             var propertyInfo = type.GetProperty(propertyName, BindingFlags.Instance | BindingFlags.Static | BindingFlags.NonPublic | BindingFlags.Public);

src/Agent/NewRelic/Agent/Extensions/Providers/Wrapper/Log4NetLogging/Log4netWrapper.cs

@@ -34,12 +34,7 @@ public class Log4netWrapper : IWrapper
 
         public CanWrapResponse CanWrap(InstrumentedMethodInfo methodInfo)
         {
-            if (!LogProviders.RegisteredLogProvider[(int)LogProvider.Log4Net])
-            {
-                return new CanWrapResponse(WrapperName.Equals(methodInfo.RequestedWrapperName));
-            }
-
-            return new CanWrapResponse(false);
+            return new CanWrapResponse(WrapperName.Equals(methodInfo.RequestedWrapperName));
         }
 
         public AfterWrappedMethodDelegate BeforeWrappedMethod(InstrumentedMethodCall instrumentedMethodCall, IAgent agent, ITransaction transaction)

src/Agent/NewRelic/Agent/Extensions/Providers/Wrapper/MicrosoftExtensionsLogging/AddProviderRegistrationWrapper.cs

@@ -22,20 +22,14 @@ public CanWrapResponse CanWrap(InstrumentedMethodInfo methodInfo)
         public AfterWrappedMethodDelegate BeforeWrappedMethod(InstrumentedMethodCall instrumentedMethodCall, IAgent agent, ITransaction transaction)
         {
             var provider = instrumentedMethodCall.MethodCall.MethodArguments[0].ToString();
-            if (LogProviders.Log4NetProviderNames.Contains(provider))
+            if (LogProviders.KnownMELProviders.Contains(provider))
             {
-                LogProviders.RegisteredLogProvider[(int)LogProvider.Log4Net] = true;
-                agent.Logger.Log(Level.Info, "Detected log4net provider in use with Microsoft.Extensions.Logging, disabling log4net instrumentation.");
+                LogProviders.KnownMELProviderEnabled = true;
+                agent.Logger.Log(Level.Info, $"Known log provider {provider} in use. Disabling Microsoft.Extensions.Logging instrumentation.");
             }
-            else if (LogProviders.SerilogProviderNames.Contains(provider))
+            else
             {
-                LogProviders.RegisteredLogProvider[(int)LogProvider.Serilog] = true;
-                agent.Logger.Log(Level.Info, "Detected Serilog provider in use with Microsoft.Extensions.Logging, disabling Serilog instrumentation.");
-            }
-            else if (LogProviders.NLogProviderNames.Contains(provider))
-            {
-                LogProviders.RegisteredLogProvider[(int)LogProvider.NLog] = true;
-                agent.Logger.Log(Level.Info, "Detected NLog provider in use with Microsoft.Extensions.Logging, disabling NLog instrumentation.");
+                agent.Logger.Log(Level.Info, $"Log provider {provider} will use Microsoft.Extensions.Logging instrumentation.");
             }
 
             return Delegates.NoOp;

src/Agent/NewRelic/Agent/Extensions/Providers/Wrapper/MicrosoftExtensionsLogging/MicrosoftLoggingWrapper.cs

@@ -9,16 +9,16 @@
 using NewRelic.Agent.Extensions.Providers.Wrapper;
 using System.Collections.Generic;
 using NewRelic.Reflection;
-using System.Dynamic;
+using Microsoft.Extensions.Logging;
+using System.Reflection;
 
 namespace NewRelic.Providers.Wrapper.MicrosoftExtensionsLogging
 {
     public class MicrosoftLoggingWrapper : IWrapper
     {
         // Cached accessor functions
         private static Func<object, dynamic> _getLoggersArray;
-        private static Func<object, object> _getLoggerProperty;
-        private static Func<object, MEL.IExternalScopeProvider> _getScopeProvider;
+        private static PropertyInfo _scopeProviderPropertyInfo;
 
         private static bool _contextDataNotSupported = false;
 
@@ -28,7 +28,11 @@ public class MicrosoftLoggingWrapper : IWrapper
 
         public CanWrapResponse CanWrap(InstrumentedMethodInfo methodInfo)
         {
-            return new CanWrapResponse(WrapperName.Equals(methodInfo.RequestedWrapperName));
+            if (!LogProviders.KnownMELProviderEnabled)
+            {
+                return new CanWrapResponse(WrapperName.Equals(methodInfo.RequestedWrapperName));
+            }
+            return new CanWrapResponse(false);
         }
 
         public AfterWrappedMethodDelegate BeforeWrappedMethod(InstrumentedMethodCall instrumentedMethodCall, IAgent agent, ITransaction transaction)
@@ -71,27 +75,24 @@ private static Dictionary<string, object> GetContextData(MEL.ILogger logger, IAg
 
             try
             {
-                // We are trying to access this property:
-                // logger.Loggers[0].Logger.ScopeProvider
+                // MEL keeps an array of scope handlers. We can ask one of them for the current scope data.
 
-                // Get the array of Loggers (logger.Loggers[])
-                var getLoggersArrayFunc = _getLoggersArray ??= VisibilityBypasser.Instance.GeneratePropertyAccessor<dynamic>(logger.GetType(), "Loggers");
+                // Get the array of ScopeLoggers (logger.ScopeLoggers[])
+                var getLoggersArrayFunc = _getLoggersArray ??= VisibilityBypasser.Instance.GeneratePropertyAccessor<dynamic>(logger.GetType(), "ScopeLoggers");
                 var loggers = getLoggersArrayFunc(logger);
 
-                // Get the first logger in the array (logger.Loggers[0])
+                // Get the first ScopeLogger in the array (logger.ScopeLoggers[0])
+                // If there is more than one scope logger, they've all received the same data, so the first
+                // one should be fine
                 object firstLogger = loggers.GetValue(0);
 
-                // Get the internal logger (logger.Loggers[0].Logger)
-                var getLoggerPropertyFunc = _getLoggerProperty ??= firstLogger.GetType().GetProperty("Logger").GetValue;
-                object internalLogger = getLoggerPropertyFunc(firstLogger);
-
-                // Get the scope provider from that logger (logger.Loggers[0].Logger.ScopeProvider)
-                var getScopeProviderFunc = _getScopeProvider ??= VisibilityBypasser.Instance.GeneratePropertyAccessor<MEL.IExternalScopeProvider>(internalLogger.GetType(), "ScopeProvider");
-                var scopeProvider = getScopeProviderFunc(internalLogger);
+                // Get the scope provider from that logger (logger.ScopeLoggers[0].ExternalScopeProvider)
+                var scopeProviderPI = _scopeProviderPropertyInfo ??= firstLogger.GetType().GetProperty("ExternalScopeProvider");
+                var scopeProvider = scopeProviderPI.GetValue(firstLogger) as IExternalScopeProvider;
 
                 // Get the context data
                 var harvestedKvps = new Dictionary<string, object>();
-                scopeProvider.ForEachScope((scopeObject, accumulatedKvps) =>
+                scopeProvider?.ForEachScope((scopeObject, accumulatedKvps) =>
                 {
                     if (scopeObject is IEnumerable<KeyValuePair<string, object>> kvps)
                     {
@@ -124,12 +125,6 @@ private AfterWrappedMethodDelegate DecorateLogMessage(MEL.ILogger logger, IAgent
                 return Delegates.NoOp;
             }
 
-            // NLog can alter the message so we want to skip MEL decoration for NLog
-            if (LogProviders.RegisteredLogProvider[(int)LogProvider.NLog])
-            {
-                return Delegates.NoOp;
-            }
-
             // uses the formatted metadata to make a single entry
             var formattedMetadata = LoggingHelpers.GetFormattedLinkingMetadata(agent);
 

src/Agent/NewRelic/Agent/Extensions/Providers/Wrapper/NLogLogging/NLogWrapper.cs

@@ -3,6 +3,7 @@
 
 using System;
 using System.Collections.Generic;
+using System.Xml.Linq;
 using NewRelic.Agent.Api;
 using NewRelic.Agent.Api.Experimental;
 using NewRelic.Agent.Extensions.Logging;
@@ -20,6 +21,7 @@ public class NLogWrapper : IWrapper
         private static Func<object, DateTime> _getTimestamp;
         private static Func<object, Exception> _getLogException;
         private static Func<object, IDictionary<object, object>> _getPropertiesDictionary;
+        private static Func<IEnumerable<KeyValuePair<string, object>>> _getScopeData;
 
         public bool IsTransactionRequired => false;
 
@@ -38,12 +40,7 @@ public AfterWrappedMethodDelegate BeforeWrappedMethod(InstrumentedMethodCall ins
             var logEvent = instrumentedMethodCall.MethodCall.MethodArguments[2];
             var logEventType = logEvent.GetType();
 
-            if (!LogProviders.RegisteredLogProvider[(int)LogProvider.NLog])
-            {
-                RecordLogMessage(logEvent, logEventType, agent);
-            }
-
-            // We want this to happen instead of MEL so no provider check here.
+            RecordLogMessage(logEvent, logEventType, agent);
             DecorateLogMessage(logEvent, logEventType, agent);
 
             return Delegates.NoOp;
@@ -127,6 +124,23 @@ private Dictionary<string, object> GetContextData(object logEvent)
                 contextData[property.Key.ToString()] = property.Value;
             }
 
+            // NLog treats and stores Properties and Scope Context differently. If we need to add support for older versions of NLog, it's two calls instead of GetAllProperties():
+            //    NLog.MappedDiagnosticsLogicalContext.GetNames()
+            //       NLog.MappedDiagnosticsLogicalContext.Get(name)
+            try
+            {
+                _getScopeData = _getScopeData ??= VisibilityBypasser.Instance.GenerateParameterlessStaticMethodCaller<IEnumerable<KeyValuePair<string, object>>>("NLog", "NLog.ScopeContext", "GetAllProperties");
+            }
+            catch
+            {
+                _getScopeData = () => new List<KeyValuePair<string, object>>();
+            }
+            var scopeData = _getScopeData();
+            foreach (var pair in scopeData)
+            {
+                contextData[pair.Key] = pair.Value;
+            }
+
             return contextData;
         }
     }

src/Agent/NewRelic/Agent/Extensions/Providers/Wrapper/SerilogLogging/NewRelicSerilogSink.cs

@@ -23,11 +23,7 @@ public NewRelicSerilogSink(IAgent agent)
 
         public void Emit(LogEvent logEvent)
         {
-            //This check is to prevent forwarding duplicate logs when Microsoft.Extensions.Logging is used.
-            if (!LogProviders.RegisteredLogProvider[(int)LogProvider.Serilog])
-            {
-                RecordLogMessage(logEvent);
-            }
+            RecordLogMessage(logEvent);
         }
 
         private void RecordLogMessage(LogEvent logEvent)

src/Agent/NewRelic/Agent/Extensions/Providers/Wrapper/SerilogLogging/SerilogCreateLoggerWrapper.cs

@@ -16,12 +16,7 @@ public class SerilogCreateLoggerWrapper : IWrapper
 
         public CanWrapResponse CanWrap(InstrumentedMethodInfo methodInfo)
         {
-            if (!LogProviders.RegisteredLogProvider[(int)LogProvider.Serilog])
-            {
-                return new CanWrapResponse(WrapperName.Equals(methodInfo.RequestedWrapperName));
-            }
-
-            return new CanWrapResponse(false);
+            return new CanWrapResponse(WrapperName.Equals(methodInfo.RequestedWrapperName));
         }
 
         public AfterWrappedMethodDelegate BeforeWrappedMethod(InstrumentedMethodCall instrumentedMethodCall, IAgent agent, ITransaction transaction)

src/Agent/NewRelic/Agent/Extensions/Providers/Wrapper/SerilogLogging/SerilogDispatchWrapper.cs

@@ -25,12 +25,7 @@ public class SerilogDispatchWrapper : IWrapper
 
         public CanWrapResponse CanWrap(InstrumentedMethodInfo methodInfo)
         {
-            if (!LogProviders.RegisteredLogProvider[(int)LogProvider.Serilog])
-            {
-                return new CanWrapResponse(WrapperName.Equals(methodInfo.RequestedWrapperName));
-            }
-
-            return new CanWrapResponse(false);
+            return new CanWrapResponse(WrapperName.Equals(methodInfo.RequestedWrapperName));
         }
 
         public AfterWrappedMethodDelegate BeforeWrappedMethod(InstrumentedMethodCall instrumentedMethodCall, IAgent agent, ITransaction transaction)

tests/Agent/IntegrationTests/IntegrationTestHelpers/AgentLogBase.cs

@@ -69,9 +69,6 @@ public abstract class AgentLogBase
         public const string SpanStreamingSuccessfullyProcessedByServerResponseLogLineRegex = FinestLogLinePrefixRegex + @"SpanStreamingService: consumer \d+ - Received gRPC Server response messages: (\d+)";
         public const string SpanStreamingResponseGrpcError = FinestLogLinePrefixRegex + @"ResponseStreamWrapper: consumer \d+ - gRPC RpcException encountered while handling gRPC server responses: (.*)";
 
-        // ContextData related messages
-        public const string ContextDataNotSupportedLogLineRegex = WarnLogLinePrefixRegex + @".* Context data is not supported for this logging framework.";
-
         public AgentLogBase(RemoteApplication remoteApplication)
         {
             _remoteApplication = remoteApplication;

tests/Agent/IntegrationTests/IntegrationTests/Logging/Common.cs

@@ -11,7 +11,9 @@ public enum LoggingFramework
         SerilogWeb,
         NLog,
         DummyMEL,
-        Sitecore
+        Sitecore,
+        SerilogEL,
+        NLogEL
     }
 
     public class LogUtils
@@ -28,6 +30,7 @@ public static string GetFrameworkName(LoggingFramework loggingFramework)
                 case LoggingFramework.Serilog:
                     return "serilog";
                 case LoggingFramework.NLog:
+                case LoggingFramework.NLogEL:
                     return "nlog";
                 case LoggingFramework.DummyMEL:
                     return "DummyMEL";
@@ -73,6 +76,7 @@ public static string GetLevelName(LoggingFramework loggingFramework, string leve
                     }
                 case LoggingFramework.SerilogWeb:
                 case LoggingFramework.Serilog:
+                case LoggingFramework.SerilogEL:
                     switch (level)
                     {
                         case "DEBUG":
@@ -91,6 +95,7 @@ public static string GetLevelName(LoggingFramework loggingFramework, string leve
                             return level;
                     }
                 case LoggingFramework.NLog:
+                case LoggingFramework.NLogEL:
                     switch (level)
                     {
                         case "NOMESSAGE":

tests/Agent/IntegrationTests/IntegrationTests/Logging/ContextDataNotSupportedTests.cs

@@ -70,11 +70,7 @@ public ContextDataNotSupportedTestsBase(TFixture fixture, ITestOutputHelper outp
         [Fact]
         public void Test()
         {
-            // verify the "not supported" warning was logged
-            var match = _fixture.AgentLog.TryGetLogLines(AgentLogBase.ContextDataNotSupportedLogLineRegex);
-            Assert.Single(match);
-
-            // verify the log data was forwarded, but *without* the attributes
+            // verify the log data was forwarded, but *without* the attributes (since our dummy logger doesn't support them)
             var expectedLogLines = new[]
             {
                 new Assertions.ExpectedLogLine

tests/Agent/IntegrationTests/IntegrationTests/Logging/ContextDataTests.cs

@@ -279,4 +279,58 @@ public SitecoreContextDataFW48Tests(ConsoleDynamicMethodFixtureFW48 fixture, ITe
     }
 
     #endregion // Sitecore
+     
+    #region SEL
+    public class SELContextDataFWLatestTests : ContextDataTestsBase<ConsoleDynamicMethodFixtureFWLatest>
+    {
+        public SELContextDataFWLatestTests(ConsoleDynamicMethodFixtureFWLatest fixture, ITestOutputHelper output)
+            : base(fixture, output, LoggingFramework.SerilogEL)
+        {
+        }
+    }
+
+    public class SELContextDataFW48Tests : ContextDataTestsBase<ConsoleDynamicMethodFixtureFW48>
+    {
+        public SELContextDataFW48Tests(ConsoleDynamicMethodFixtureFW48 fixture, ITestOutputHelper output)
+            : base(fixture, output, LoggingFramework.SerilogEL)
+        {
+        }
+    }
+
+    public class SELContextDataCoreLatestTests : ContextDataTestsBase<ConsoleDynamicMethodFixtureCoreLatest>
+    {
+        public SELContextDataCoreLatestTests(ConsoleDynamicMethodFixtureCoreLatest fixture, ITestOutputHelper output)
+            : base(fixture, output, LoggingFramework.SerilogEL)
+        {
+        }
+    }
+
+    public class SELContextDataCoreOldestTests : ContextDataTestsBase<ConsoleDynamicMethodFixtureCoreOldest>
+    {
+        public SELContextDataCoreOldestTests(ConsoleDynamicMethodFixtureCoreOldest fixture, ITestOutputHelper output)
+            : base(fixture, output, LoggingFramework.SerilogEL)
+        {
+        }
+    }
+
+    #endregion // SEL
+
+    #region NEL
+    public class NELContextDataFWLatestTests : ContextDataTestsBase<ConsoleDynamicMethodFixtureFWLatest>
+    {
+        public NELContextDataFWLatestTests(ConsoleDynamicMethodFixtureFWLatest fixture, ITestOutputHelper output)
+            : base(fixture, output, LoggingFramework.NLogEL)
+        {
+        }
+    }
+
+    public class NELContextDataCoreLatestTests : ContextDataTestsBase<ConsoleDynamicMethodFixtureCoreLatest>
+    {
+        public NELContextDataCoreLatestTests(ConsoleDynamicMethodFixtureCoreLatest fixture, ITestOutputHelper output)
+            : base(fixture, output, LoggingFramework.NLogEL)
+        {
+        }
+    }
+
+    #endregion // NEL
 }