Fix Trace Id Injection NullReferenceException with NLog 1.0.0.505 (Da…

…taDog#614)

Issue:
Currently using the Trace Id Injection fails with a NullReferenceException when the instrumented application is using NLog 1.0.0.505. This occurs because the LibLog library we use to detect the instrumented application's logging framework assumes that all versions of NLog have the type `NLog.MappedDiagnosticsContext` for using the Mdc features. Unfortunately this is incorrect in one case: the very first NLog library v1.0.0.505 had its Mdc features in a type named `NLog.MDC`. Rather than vendor LibLog to support this, for now we will catch the issue and disable Trace Id Injection for the application.

Changes:
- Add new reproduction project NLog10LogsInjection.NullReferenceException and an associated CI test case to reproduce issue with DD_LOGS_INJECTION=true on NLog v1.0.0.505
- Add the fix to catch the inability to add to the MDC of the application logging framework.
- Additionally, perform small refactoring of CI test harness.

Datadog.Trace.sln

@@ -291,6 +291,8 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Samples.AspNetCoreMvc31", "
 EndProject
 Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Samples.AspNetCoreMvc21", "samples\Samples.AspNetCoreMvc21\Samples.AspNetCoreMvc21.csproj", "{D141BD06-DD95-4CAF-85CD-657116E0DAD4}"
 EndProject
+Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "NLog10LogsInjection.NullReferenceException", "reproductions\NLog10LogsInjection.NullReferenceException\NLog10LogsInjection.NullReferenceException.csproj", "{6209C19B-42E4-4FCF-A539-FD1E4F4A34DB}"
+EndProject
 Global
 	GlobalSection(SolutionConfigurationPlatforms) = preSolution
 		Debug|Any CPU = Debug|Any CPU
@@ -1003,6 +1005,16 @@ Global
 		{D141BD06-DD95-4CAF-85CD-657116E0DAD4}.Release|x64.Build.0 = Release|x64
 		{D141BD06-DD95-4CAF-85CD-657116E0DAD4}.Release|x86.ActiveCfg = Release|x86
 		{D141BD06-DD95-4CAF-85CD-657116E0DAD4}.Release|x86.Build.0 = Release|x86
+		{6209C19B-42E4-4FCF-A539-FD1E4F4A34DB}.Debug|Any CPU.ActiveCfg = Debug|x86
+		{6209C19B-42E4-4FCF-A539-FD1E4F4A34DB}.Debug|x64.ActiveCfg = Debug|x64
+		{6209C19B-42E4-4FCF-A539-FD1E4F4A34DB}.Debug|x64.Build.0 = Debug|x64
+		{6209C19B-42E4-4FCF-A539-FD1E4F4A34DB}.Debug|x86.ActiveCfg = Debug|x86
+		{6209C19B-42E4-4FCF-A539-FD1E4F4A34DB}.Debug|x86.Build.0 = Debug|x86
+		{6209C19B-42E4-4FCF-A539-FD1E4F4A34DB}.Release|Any CPU.ActiveCfg = Release|x86
+		{6209C19B-42E4-4FCF-A539-FD1E4F4A34DB}.Release|x64.ActiveCfg = Release|x64
+		{6209C19B-42E4-4FCF-A539-FD1E4F4A34DB}.Release|x64.Build.0 = Release|x64
+		{6209C19B-42E4-4FCF-A539-FD1E4F4A34DB}.Release|x86.ActiveCfg = Release|x86
+		{6209C19B-42E4-4FCF-A539-FD1E4F4A34DB}.Release|x86.Build.0 = Release|x86
 	EndGlobalSection
 	GlobalSection(SolutionProperties) = preSolution
 		HideSolutionNode = FALSE
@@ -1075,6 +1087,7 @@ Global
 		{8B457E8F-8716-4F29-BBE2-DD6C7BC4AC37} = {AA6F5582-3B71-49AC-AA39-8F7815AC46BE}
 		{303F8E41-691F-4453-AB7D-88A0036C0465} = {AA6F5582-3B71-49AC-AA39-8F7815AC46BE}
 		{D141BD06-DD95-4CAF-85CD-657116E0DAD4} = {AA6F5582-3B71-49AC-AA39-8F7815AC46BE}
+		{6209C19B-42E4-4FCF-A539-FD1E4F4A34DB} = {550AE553-2BBB-4021-B55A-137EF31A6B1F}
 	EndGlobalSection
 	GlobalSection(ExtensibilityGlobals) = postSolution
 		SolutionGuid = {160A1D00-1F5B-40F8-A155-621B4459D78F}

reproductions/NLog10LogsInjection.NullReferenceException/NLog.config

@@ -0,0 +1,11 @@
+<?xml version="1.0" encoding="utf-8" ?>
+<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
+      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
+    <targets>
+        <target name="logfile" xsi:type="File" fileName="file.txt" />
+    </targets>
+
+    <rules>
+        <logger name="*" minlevel="Trace" writeTo="logfile" />
+    </rules>
+</nlog>

reproductions/NLog10LogsInjection.NullReferenceException/NLog10LogsInjection.NullReferenceException.csproj

@@ -0,0 +1,17 @@
+<Project Sdk="Microsoft.NET.Sdk">
+
+  <PropertyGroup>
+    <TargetFrameworks Condition="'$(OS)' == 'Windows_NT'">net452;net461</TargetFrameworks>
+    <IsPackable>false</IsPackable>
+    <ExcludeManagedProfiler>true</ExcludeManagedProfiler>
+  </PropertyGroup>
+
+  <ItemGroup>
+    <PackageReference Include="NLog" Version="1.0.0.505" />
+  </ItemGroup>
+
+  <ItemGroup>
+    <ProjectReference Include="..\..\src\Datadog.Trace\Datadog.Trace.csproj" />
+  </ItemGroup>
+
+</Project>

reproductions/NLog10LogsInjection.NullReferenceException/Program.cs

@@ -0,0 +1,29 @@
+using Datadog.Trace;
+using NLog;
+using System;
+using System.Threading.Tasks;
+
+namespace NLog10LogsInjection.NullReferenceException
+{
+    class Program
+    {
+        private static readonly Logger Logger = LogManager.GetCurrentClassLogger();
+
+        static int Main(string[] args)
+        {
+            using (var scope = Tracer.Instance.StartActive("Main"))
+            {
+                Logger.Info("Message during a trace.");
+
+                using (var innerScope = Tracer.Instance.StartActive("Main-Inner"))
+                {
+                    Logger.Info("Inner message during a trace.");
+                }
+            }
+
+            Console.WriteLine("Successfully created a trace with two spans and didn't crash. Delay for five seconds to flush the trace.");
+            Task.Delay(TimeSpan.FromSeconds(5)).GetAwaiter().GetResult();
+            return 0;
+        }
+    }
+}

reproductions/NLog10LogsInjection.NullReferenceException/Properties/launchSettings.json

@@ -0,0 +1,11 @@
+{
+    "profiles": {
+      "NLog10LogsInjection.NullReferenceException": {
+        "commandName": "Project",
+        "environmentVariables": {
+          "DD_LOGS_INJECTION": "true"
+        },
+        "nativeDebugging": true
+      }
+    }
+  }

src/Datadog.Trace/Logging/LibLogScopeEventSubscriber.cs

@@ -25,6 +25,8 @@ internal class LibLogScopeEventSubscriber : IDisposable
         //            it is only valid to add the properties once and unset them once.
         private readonly ConcurrentStack<IDisposable> _contextDisposalStack = new ConcurrentStack<IDisposable>();
 
+        private bool _safeToAddToMdc = true;
+
         // IMPORTANT: For all logging frameworks, do not set any default values for
         //            "dd.trace_id" and "dd.span_id" when initializing the subscriber
         //            because the Tracer may be initialized at a time when it is not safe
@@ -129,13 +131,26 @@ private void RemoveAllCorrelationIdentifierContexts()
 
         private void SetCorrelationIdentifierContext(ulong traceId, ulong spanId)
         {
-            // TODO: Debug logs
-            _contextDisposalStack.Push(
-                LogProvider.OpenMappedContext(
-                    CorrelationIdentifier.TraceIdKey, traceId.ToString(), destructure: false));
-            _contextDisposalStack.Push(
-                LogProvider.OpenMappedContext(
-                    CorrelationIdentifier.SpanIdKey, spanId.ToString(), destructure: false));
+            if (!_safeToAddToMdc)
+            {
+                return;
+            }
+
+            try
+            {
+                // TODO: Debug logs
+                _contextDisposalStack.Push(
+                    LogProvider.OpenMappedContext(
+                        CorrelationIdentifier.TraceIdKey, traceId.ToString(), destructure: false));
+                _contextDisposalStack.Push(
+                    LogProvider.OpenMappedContext(
+                        CorrelationIdentifier.SpanIdKey, spanId.ToString(), destructure: false));
+            }
+            catch (Exception)
+            {
+                _safeToAddToMdc = false;
+                RemoveAllCorrelationIdentifierContexts();
+            }
         }
     }
 }

test/Datadog.Trace.ClrProfiler.IntegrationTests/Helpers/TestHelper.cs

@@ -18,13 +18,13 @@ namespace Datadog.Trace.ClrProfiler.IntegrationTests
 {
     public abstract class TestHelper
     {
-        protected TestHelper(string sampleAppName, string samplePathOverrides, ITestOutputHelper output, string disabledIntegrations = null)
-            : this(new EnvironmentHelper(sampleAppName, typeof(TestHelper), output, samplePathOverrides, disabledIntegrations), output)
+        protected TestHelper(string sampleAppName, string samplePathOverrides, ITestOutputHelper output)
+            : this(new EnvironmentHelper(sampleAppName, typeof(TestHelper), output, samplePathOverrides), output)
         {
         }
 
-        protected TestHelper(string sampleAppName, ITestOutputHelper output, string disabledIntegrations = null)
-            : this(new EnvironmentHelper(sampleAppName, typeof(TestHelper), output, disabledIntegrations), output)
+        protected TestHelper(string sampleAppName, ITestOutputHelper output)
+            : this(new EnvironmentHelper(sampleAppName, typeof(TestHelper), output), output)
         {
         }
 
@@ -221,6 +221,11 @@ protected void EnableDebugMode()
             EnvironmentHelper.DebugModeEnabled = true;
         }
 
+        protected void SetEnvironmentVariable(string key, string value)
+        {
+            EnvironmentHelper.CustomEnvironmentVariables.Add(key, value);
+        }
+
         protected async Task AssertHttpSpan(
             string path,
             MockTracerAgent agent,

test/Datadog.Trace.ClrProfiler.IntegrationTests/LoadTests/LoadTestBase.cs

@@ -140,15 +140,14 @@ protected void RunLoadTestPart(LoadTestPart loadTestPart)
             {
                 // .NET Core
                 startInfo = new ProcessStartInfo(executable, $"{applicationPath} {commandLineArgs}");
-                environmentHelper.SetEnvironmentVariableDefaults(agentPort, aspNetPort, executable, startInfo.EnvironmentVariables);
             }
             else
             {
                 // .NET Framework
                 startInfo = new ProcessStartInfo(executable, $"{commandLineArgs}");
-                environmentHelper.SetEnvironmentVariableDefaults(agentPort, aspNetPort, executable, startInfo.EnvironmentVariables);
             }
 
+            environmentHelper.SetEnvironmentVariables(agentPort, aspNetPort, executable, startInfo.EnvironmentVariables);
             startInfo.UseShellExecute = false;
             startInfo.CreateNoWindow = true;
             startInfo.RedirectStandardOutput = true;

test/Datadog.Trace.ClrProfiler.IntegrationTests/SmokeTests/NLog10LogsInjectionNullReferenceExceptionSmokeTest.cs

@@ -0,0 +1,22 @@
+using Datadog.Trace.ClrProfiler.IntegrationTests.Helpers;
+using Xunit;
+using Xunit.Abstractions;
+
+namespace Datadog.Trace.ClrProfiler.IntegrationTests.SmokeTests
+{
+    public class NLog10LogsInjectionNullReferenceExceptionSmokeTest : SmokeTestBase
+    {
+        public NLog10LogsInjectionNullReferenceExceptionSmokeTest(ITestOutputHelper output)
+            : base(output, "NLog10LogsInjection.NullReferenceException", maxTestRunSeconds: 45)
+        {
+            SetEnvironmentVariable("DD_LOGS_INJECTION", "true");
+        }
+
+        [TargetFrameworkVersionsFact("net452;net461")]
+        [Trait("Category", "Smoke")]
+        public void NoExceptions()
+        {
+            CheckForSmoke(shouldDeserializeTraces: false);
+        }
+    }
+}

test/Datadog.Trace.ClrProfiler.IntegrationTests/SmokeTests/SmokeTestBase.cs

@@ -32,6 +32,11 @@ protected SmokeTestBase(
 
         protected bool AssumeSuccessOnTimeout { get; set; }
 
+        protected void SetEnvironmentVariable(string key, string value)
+        {
+            EnvironmentHelper.CustomEnvironmentVariables.Add(key, value);
+        }
+
         /// <summary>
         /// Method to execute a smoke test.
         /// </summary>
@@ -62,15 +67,15 @@ protected void CheckForSmoke(bool shouldDeserializeTraces = true)
             {
                 // .NET Core
                 startInfo = new ProcessStartInfo(executable, $"{applicationPath}");
-                EnvironmentHelper.SetEnvironmentVariableDefaults(agentPort, aspNetCorePort, executable, startInfo.EnvironmentVariables);
             }
             else
             {
                 // .NET Framework
                 startInfo = new ProcessStartInfo(executable);
-                EnvironmentHelper.SetEnvironmentVariableDefaults(agentPort, aspNetCorePort, executable, startInfo.EnvironmentVariables);
             }
 
+            EnvironmentHelper.SetEnvironmentVariables(agentPort, aspNetCorePort, executable, startInfo.EnvironmentVariables);
+
             startInfo.UseShellExecute = false;
             startInfo.CreateNoWindow = true;
             startInfo.RedirectStandardOutput = true;

test/Datadog.Trace.TestHelpers/EnvironmentHelper.cs

@@ -1,4 +1,5 @@
 using System;
+using System.Collections.Generic;
 using System.Collections.Specialized;
 using System.IO;
 using System.Reflection;
@@ -24,7 +25,6 @@ public class EnvironmentHelper
         private readonly string _runtime;
         private readonly bool _isCoreClr;
         private readonly string _samplesDirectory;
-        private readonly string _disabledIntegrations;
         private readonly Type _anchorType;
         private readonly Assembly _anchorAssembly;
         private readonly TargetFrameworkAttribute _targetFramework;
@@ -38,13 +38,11 @@ public EnvironmentHelper(
             Type anchorType,
             ITestOutputHelper output,
             string samplesDirectory = "samples",
-            string disabledIntegrations = null,
             bool prependSamplesToAppName = true,
             bool requiresProfiling = true)
         {
             SampleName = sampleName;
             _samplesDirectory = samplesDirectory ?? "samples";
-            _disabledIntegrations = disabledIntegrations;
             _anchorType = anchorType;
             _anchorAssembly = Assembly.GetAssembly(_anchorType);
             _targetFramework = _anchorAssembly.GetCustomAttribute<TargetFrameworkAttribute>();
@@ -69,6 +67,10 @@ public EnvironmentHelper(
                           : string.Empty;
         }
 
+        public bool DebugModeEnabled { get; set; }
+
+        public Dictionary<string, string> CustomEnvironmentVariables { get; set; } = new Dictionary<string, string>();
+
         public string SampleName { get; }
 
         public string FullSampleName => $"{_appNamePrepend}{SampleName}";
@@ -137,7 +139,7 @@ public static void ClearProfilerEnvironmentVariables()
             }
         }
 
-        public void SetEnvironmentVariableDefaults(
+        public void SetEnvironmentVariables(
             int agentPort,
             int aspNetCorePort,
             string processPath,
@@ -168,6 +170,11 @@ public void SetEnvironmentVariableDefaults(
                 processName = Path.GetFileName(processPath);
             }
 
+            if (DebugModeEnabled)
+            {
+                environmentVariables["DD_TRACE_DEBUG"] = "1";
+            }
+
             environmentVariables["DD_PROFILER_PROCESSES"] = processName;
 
             string integrations = string.Join(";", GetIntegrationsFilePaths());
@@ -187,9 +194,9 @@ public void SetEnvironmentVariableDefaults(
                 }
             }
 
-            if (_disabledIntegrations != null)
+            foreach (var key in CustomEnvironmentVariables.Keys)
             {
-                environmentVariables["DD_DISABLED_INTEGRATIONS"] = _disabledIntegrations;
+                environmentVariables[key] = CustomEnvironmentVariables[key];
             }
         }
 

test/Datadog.Trace.TestHelpers/ProfilerHelper.cs

@@ -36,15 +36,15 @@ public static Process StartProcessWithProfiler(
             {
                 // .NET Core
                 startInfo = new ProcessStartInfo(executable, $"{applicationPath} {arguments ?? string.Empty}");
-                environmentHelper.SetEnvironmentVariableDefaults(traceAgentPort, aspNetCorePort, executable, startInfo.EnvironmentVariables);
             }
             else
             {
                 // .NET Framework
                 startInfo = new ProcessStartInfo(executable, $"{arguments ?? string.Empty}");
-                environmentHelper.SetEnvironmentVariableDefaults(traceAgentPort, aspNetCorePort, executable, startInfo.EnvironmentVariables);
             }
 
+            environmentHelper.SetEnvironmentVariables(traceAgentPort, aspNetCorePort, executable, startInfo.EnvironmentVariables);
+
             startInfo.UseShellExecute = false;
             startInfo.CreateNoWindow = true;
             startInfo.RedirectStandardOutput = true;