Fix DD_LOGS_INJECTION crash with the ASP.NET integration

Datadog.Trace.sln

@@ -104,13 +104,17 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Datadog.Trace.ClrProfiler.I
 		{3493346B-44F6-4F50-8FB4-51D0090DF544} = {3493346B-44F6-4F50-8FB4-51D0090DF544}
 		{F47F206E-4CCA-4AD0-AEBA-FD9F491E05EC} = {F47F206E-4CCA-4AD0-AEBA-FD9F491E05EC}
 		{C0C8D381-D6B9-4C76-9428-F40F2FA93A9A} = {C0C8D381-D6B9-4C76-9428-F40F2FA93A9A}
+		{DF923186-5397-4E15-A95B-F15C8327ED53} = {DF923186-5397-4E15-A95B-F15C8327ED53}
 		{FA487690-E88C-4A57-9187-B71CB70C1AAE} = {FA487690-E88C-4A57-9187-B71CB70C1AAE}
+		{E1706893-D3A5-43B9-9036-AEF49DB9600B} = {E1706893-D3A5-43B9-9036-AEF49DB9600B}
 		{086FF8A0-9CEE-470A-9751-78B0F1340649} = {086FF8A0-9CEE-470A-9751-78B0F1340649}
 		{3CDCE3AA-7CAF-4A27-B1D3-9D558B74D084} = {3CDCE3AA-7CAF-4A27-B1D3-9D558B74D084}
 		{C98950B1-DC4B-43DA-974F-EF2CF325EC2B} = {C98950B1-DC4B-43DA-974F-EF2CF325EC2B}
 		{8E1555D1-13D5-4DBF-9631-117D840C3158} = {8E1555D1-13D5-4DBF-9631-117D840C3158}
 		{DD3E8ED8-A0E4-482E-A5ED-115E21D543C0} = {DD3E8ED8-A0E4-482E-A5ED-115E21D543C0}
 		{387E25D9-6B09-4C11-ADDC-EDE1A3311728} = {387E25D9-6B09-4C11-ADDC-EDE1A3311728}
+		{42FA33DD-AEA3-4FF3-8319-F30244A666A4} = {42FA33DD-AEA3-4FF3-8319-F30244A666A4}
+		{35F581E9-3D7C-4E80-8DFF-D437B0D86710} = {35F581E9-3D7C-4E80-8DFF-D437B0D86710}
 		{DAD5E1F2-A158-4624-9FB4-C89E98DFF0D4} = {DAD5E1F2-A158-4624-9FB4-C89E98DFF0D4}
 		{DA0A44FB-D562-4776-AAFB-8266E78AA1A6} = {DA0A44FB-D562-4776-AAFB-8266E78AA1A6}
 	EndProjectSection
@@ -263,6 +267,10 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "UpdateVendors", "tools\Upda
 EndProject
 Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "SynchronizeInstaller", "tools\SynchronizeInstaller\SynchronizeInstaller.csproj", "{EBDDF6D7-59B8-4831-80C6-458C1ABBFC63}"
 EndProject
+Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Log4Net.SerializationException", "reproductions\Log4Net.SerializationException\Log4Net.SerializationException.csproj", "{35F581E9-3D7C-4E80-8DFF-D437B0D86710}"
+EndProject
+Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "ApplicationWithLog4Net", "reproduction-dependencies\ApplicationWithLog4Net\ApplicationWithLog4Net.csproj", "{1C34D970-6081-4EFA-8F2F-5AD2B146AC58}"
+EndProject
 Global
 	GlobalSection(SolutionConfigurationPlatforms) = preSolution
 		Debug|Any CPU = Debug|Any CPU
@@ -859,6 +867,26 @@ Global
 		{EBDDF6D7-59B8-4831-80C6-458C1ABBFC63}.Release|x64.Build.0 = Release|Any CPU
 		{EBDDF6D7-59B8-4831-80C6-458C1ABBFC63}.Release|x86.ActiveCfg = Release|Any CPU
 		{EBDDF6D7-59B8-4831-80C6-458C1ABBFC63}.Release|x86.Build.0 = Release|Any CPU
+		{35F581E9-3D7C-4E80-8DFF-D437B0D86710}.Debug|Any CPU.ActiveCfg = Debug|x86
+		{35F581E9-3D7C-4E80-8DFF-D437B0D86710}.Debug|x64.ActiveCfg = Debug|x64
+		{35F581E9-3D7C-4E80-8DFF-D437B0D86710}.Debug|x64.Build.0 = Debug|x64
+		{35F581E9-3D7C-4E80-8DFF-D437B0D86710}.Debug|x86.ActiveCfg = Debug|x86
+		{35F581E9-3D7C-4E80-8DFF-D437B0D86710}.Debug|x86.Build.0 = Debug|x86
+		{35F581E9-3D7C-4E80-8DFF-D437B0D86710}.Release|Any CPU.ActiveCfg = Release|x86
+		{35F581E9-3D7C-4E80-8DFF-D437B0D86710}.Release|x64.ActiveCfg = Release|x64
+		{35F581E9-3D7C-4E80-8DFF-D437B0D86710}.Release|x64.Build.0 = Release|x64
+		{35F581E9-3D7C-4E80-8DFF-D437B0D86710}.Release|x86.ActiveCfg = Release|x86
+		{35F581E9-3D7C-4E80-8DFF-D437B0D86710}.Release|x86.Build.0 = Release|x86
+		{1C34D970-6081-4EFA-8F2F-5AD2B146AC58}.Debug|Any CPU.ActiveCfg = Debug|x86
+		{1C34D970-6081-4EFA-8F2F-5AD2B146AC58}.Debug|x64.ActiveCfg = Debug|x64
+		{1C34D970-6081-4EFA-8F2F-5AD2B146AC58}.Debug|x64.Build.0 = Debug|x64
+		{1C34D970-6081-4EFA-8F2F-5AD2B146AC58}.Debug|x86.ActiveCfg = Debug|x86
+		{1C34D970-6081-4EFA-8F2F-5AD2B146AC58}.Debug|x86.Build.0 = Debug|x86
+		{1C34D970-6081-4EFA-8F2F-5AD2B146AC58}.Release|Any CPU.ActiveCfg = Release|x86
+		{1C34D970-6081-4EFA-8F2F-5AD2B146AC58}.Release|x64.ActiveCfg = Release|x64
+		{1C34D970-6081-4EFA-8F2F-5AD2B146AC58}.Release|x64.Build.0 = Release|x64
+		{1C34D970-6081-4EFA-8F2F-5AD2B146AC58}.Release|x86.ActiveCfg = Release|x86
+		{1C34D970-6081-4EFA-8F2F-5AD2B146AC58}.Release|x86.Build.0 = Release|x86
 	EndGlobalSection
 	GlobalSection(SolutionProperties) = preSolution
 		HideSolutionNode = FALSE
@@ -920,6 +948,8 @@ Global
 		{472DBA92-4FEA-4B9A-BA70-0E97B942E12D} = {FA03944C-2391-4C25-8979-2E078A8CE0DD}
 		{72FB583A-A1B0-4B5F-8658-617B100DCD8E} = {5D8E1F81-B820-4736-B797-271B0FE787EE}
 		{EBDDF6D7-59B8-4831-80C6-458C1ABBFC63} = {5D8E1F81-B820-4736-B797-271B0FE787EE}
+		{35F581E9-3D7C-4E80-8DFF-D437B0D86710} = {550AE553-2BBB-4021-B55A-137EF31A6B1F}
+		{1C34D970-6081-4EFA-8F2F-5AD2B146AC58} = {641C9C61-53FD-4504-B8D9-84008BDB89D1}
 	EndGlobalSection
 	GlobalSection(ExtensibilityGlobals) = postSolution
 		SolutionGuid = {160A1D00-1F5B-40F8-A155-621B4459D78F}

reproduction-dependencies/ApplicationWithLog4Net/ApplicationWithLog4Net.csproj

@@ -0,0 +1,21 @@
+<Project Sdk="Microsoft.NET.Sdk">
+
+  <PropertyGroup>
+    <OutputType>Library</OutputType>
+    <TargetFrameworks>net45</TargetFrameworks>
+    <Platforms>x64;x86</Platforms>
+    <PlatformTarget>$(Platform)</PlatformTarget>
+    <IsPackable>false</IsPackable>
+  </PropertyGroup>
+
+  <ItemGroup>
+    <PackageReference Include="log4net" Version="2.0.8" />
+  </ItemGroup>
+
+  <ItemGroup>
+    <None Update="log4net.config">
+      <CopyToOutputDirectory>PreserveNewest</CopyToOutputDirectory>
+    </None>
+  </ItemGroup>
+
+</Project>

reproduction-dependencies/ApplicationWithLog4Net/Program.cs

@@ -0,0 +1,35 @@
+
+using System;
+using System.IO;
+using Datadog.Trace.ClrProfiler.Integrations;
+using log4net;
+using log4net.Config;
+
+namespace ApplicationWithLog4Net
+{
+    public class Program : MarshalByRefObject
+    {
+        private static readonly ILog log = LogManager.GetLogger(typeof(Program));
+
+        static void Main(string[] args)
+        {
+            var logRepository = LogManager.GetRepository(typeof(Program).Assembly);
+            XmlConfigurator.Configure(logRepository, new FileInfo("log4net.config"));
+
+            log.Info("Message");
+        }
+
+        public override string ToString()
+        {
+            // Set DD_LOGS_INJECTION to enable the automatic trace injection
+            Environment.SetEnvironmentVariable("DD_LOGS_INJECTION", "true");
+
+            // Let's call AspNetStartup.Register now
+            // This will create a Tracer and, if buggy, store items in the CallContext
+            // which will need to be passed by ref or deserialized when transitioning AppDomains
+            AspNetStartup.Register();
+
+            return "ApplicationWithLog4Net.Program";
+        }
+    }
+}

reproduction-dependencies/ApplicationWithLog4Net/log4net.config

@@ -0,0 +1,19 @@
+<?xml version="1.0" encoding="utf-8" ?>
+<configuration>
+    <configSections>
+        <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
+    </configSections>
+    <log4net>
+        <appender name="textfile" type="log4net.Appender.FileAppender">
+            <file value="textfile.log" />
+            <layout type="log4net.Layout.PatternLayout">
+                <conversionPattern value="%date [%thread] %-5level %logger [%ndc] - %message%newline" />
+            </layout>
+        </appender>
+
+        <root>
+            <level value="INFO" />
+            <appender-ref ref="textfile" />
+        </root>
+    </log4net>
+</configuration>

reproductions/Log4Net.SerializationException/Log4Net.SerializationException.csproj

@@ -0,0 +1,26 @@
+<Project Sdk="Microsoft.NET.Sdk">
+
+  <PropertyGroup>
+    <TargetFrameworks Condition="'$(OS)' == 'Windows_NT'">net452;net461</TargetFrameworks>
+    <IsPackable>false</IsPackable>
+    <ExcludeManagedProfiler>true</ExcludeManagedProfiler>
+    <ExcludeNativeProfiler>true</ExcludeNativeProfiler>
+  </PropertyGroup>
+
+  <ItemGroup>
+    <ProjectReference Include="..\..\reproduction-dependencies\ApplicationWithLog4Net\ApplicationWithLog4Net.csproj" />
+  </ItemGroup>
+
+  <Target Name="AfterBuildMoveApplicationWithLog4Net" AfterTargets="AfterBuild">
+    <ItemGroup>
+      <!-- Subfolders of the output directory should each be a target framework -->
+      <OtherApplicationFiles Include="$(OutputPath)*.dll" />
+      <OtherApplicationFiles Include="$(OutputPath)*.xml" />
+      <OtherApplicationFiles Include="$(OutputPath)*.pdb" Exclude="$(OutputPath)Log4Net.SerializationException.pdb" />
+      <OtherApplicationFiles Include="$(OutputPath)log4net.config" />
+    </ItemGroup>
+
+    <Move SourceFiles="@(OtherApplicationFiles)" DestinationFolder="$(OutputPath)ApplicationFiles" />
+  </Target>
+
+</Project>

reproductions/Log4Net.SerializationException/Program.cs

@@ -0,0 +1,45 @@
+
+using System;
+using System.IO;
+using System.Reflection;
+using System.Security.Policy;
+
+namespace Log4Net.SerializationException
+{
+    public class Program
+    {
+        public static int Main(string[] args)
+        {
+            // The library we want to run was built and copied to the ApplicationFiles subdirectory
+            // Create an AppDomain with that directory as the appBasePath
+            var entryDirectory = Directory.GetParent(Assembly.GetEntryAssembly().Location);
+            var applicationFilesDirectory = Path.Combine(entryDirectory.FullName, "ApplicationFiles");
+            var applicationAppDomain = AppDomain.CreateDomain("ApplicationAppDomain", null, applicationFilesDirectory, applicationFilesDirectory, false);
+            var objectHandle = Activator.CreateInstance(applicationAppDomain, "ApplicationWithLog4Net", "ApplicationWithLog4Net.Program");
+
+            // Get the program type so we can call into it from this AppDomain
+            var programObject = objectHandle.Unwrap();
+
+            try
+            {
+                // Test that when transition back to this AppDomain, there are no serialization problems
+                // This would happen if any values were stored in data slots
+                Console.WriteLine("Calling the ApplicationWithLog4Net.Program in a separate AppDomain");
+                programObject.ToString();
+            }
+            catch (Exception ex)
+            {
+                Console.Error.WriteLine(ex);
+                return (int)ExitCode.UnknownError;
+            }
+
+            return (int)ExitCode.Success;
+        }
+
+        enum ExitCode : int
+        {
+            Success = 0,
+            UnknownError = -10
+        }
+    }
+}

src/Datadog.Trace/Logging/LibLogScopeEventSubscriber.cs

@@ -22,9 +22,21 @@ internal class LibLogScopeEventSubscriber : IDisposable
         // IMPORTANT: Serilog -- The logging contexts (throughout the entire application)
         //            are maintained in a stack, as opposed to a map, and must be closed
         //            in reverse-order of opening. When operating on the stack-based model,
-        //            it is only valid to add the properties once unset them once.
+        //            it is only valid to add the properties once and unset them once.
         private readonly ConcurrentStack<IDisposable> _contextDisposalStack = new ConcurrentStack<IDisposable>();
 
+        // 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
+        //            to add properties logging context of the underlying logging framework.
+        //
+        //            Failure to abide by this can cause a SerializationException when
+        //            control is passed from one AppDomain to another where the originating
+        //            AppDomain used a logging framework that stored logging context properties
+        //            inside the System.Runtime.Remoting.Messaging.CallContext structure
+        //            but the target AppDomain is unable to de-serialize the object --
+        //            this can easily happen if the target AppDomain cannot find/load the
+        //            logging framework assemblies.
         public LibLogScopeEventSubscriber(IScopeManager scopeManager)
         {
             _scopeManager = scopeManager;
@@ -39,7 +51,6 @@ public LibLogScopeEventSubscriber(IScopeManager scopeManager)
             }
             else
             {
-                SetDefaultValues();
                 _scopeManager.SpanActivated += MapOnSpanActivated;
                 _scopeManager.TraceEnded += MapOnTraceEnded;
             }

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

@@ -0,0 +1,21 @@
+using Datadog.Trace.ClrProfiler.IntegrationTests.Helpers;
+using Xunit;
+using Xunit.Abstractions;
+
+namespace Datadog.Trace.ClrProfiler.IntegrationTests.SmokeTests
+{
+    public class Log4NetSerializationExceptionSmokeTest : SmokeTestBase
+    {
+        public Log4NetSerializationExceptionSmokeTest(ITestOutputHelper output)
+            : base(output, "Log4Net.SerializationException", maxTestRunSeconds: 60)
+        {
+        }
+
+        [TargetFrameworkVersionsFact("net452;net461")]
+        [Trait("Category", "Smoke")]
+        public void NoExceptions()
+        {
+            CheckForSmoke();
+        }
+    }
+}

test/Datadog.Trace.Tests/Logging/Log4NetLogProviderTests.cs

@@ -47,6 +47,14 @@ public void EnabledLibLogSubscriberAddsTraceData()
             int logIndex = 0;
             LoggingEvent logEvent;
 
+            // The first log should not have dd.span_id or dd.trace_id
+            // Scope: N/A
+            // Custom property: N/A
+            logEvent = filteredLogs[logIndex++];
+            Assert.DoesNotContain(CorrelationIdentifier.SpanIdKey, logEvent.Properties.GetKeys());
+            Assert.DoesNotContain(CorrelationIdentifier.TraceIdKey, logEvent.Properties.GetKeys());
+            Assert.DoesNotContain(LoggingProviderTestHelpers.CustomPropertyName, logEvent.Properties.GetKeys());
+
             // Scope: Parent scope
             // Custom property: N/A
             logEvent = filteredLogs[logIndex++];
@@ -112,6 +120,13 @@ public void DisabledLibLogSubscriberDoesNotAddTraceData()
             Assert.DoesNotContain(CorrelationIdentifier.TraceIdKey, logEvent.Properties.GetKeys());
             Assert.DoesNotContain(LoggingProviderTestHelpers.CustomPropertyName, logEvent.Properties.GetKeys());
 
+            // Scope: N/A
+            // Custom property: N/A
+            logEvent = filteredLogs[logIndex++];
+            Assert.DoesNotContain(CorrelationIdentifier.SpanIdKey, logEvent.Properties.GetKeys());
+            Assert.DoesNotContain(CorrelationIdentifier.TraceIdKey, logEvent.Properties.GetKeys());
+            Assert.DoesNotContain(LoggingProviderTestHelpers.CustomPropertyName, logEvent.Properties.GetKeys());
+
             // Scope: N/A
             // Custom property: SET
             logEvent = filteredLogs[logIndex++];

test/Datadog.Trace.Tests/Logging/LoggingProviderTestHelpers.cs

@@ -34,6 +34,8 @@ internal static Tracer InitializeTracer(bool enableLogsInjection)
 
         internal static void PerformParentChildScopeSequence(Tracer tracer, ILog logger, Func<string, object, bool, IDisposable> openMappedContext, out Scope parentScope, out Scope childScope)
         {
+            logger.Log(LogLevel.Info, () => $"{LogPrefix}Logged before starting/activating a scope");
+
             parentScope = tracer.StartActive("parent");
             logger.Log(LogLevel.Info, () => $"{LogPrefix}Started and activated parent scope.");
 

test/Datadog.Trace.Tests/Logging/NLogLogProviderTests.cs

@@ -59,6 +59,14 @@ public void EnabledLibLogSubscriberAddsTraceData()
             int logIndex = 0;
             string logString;
 
+            // The first log should not have dd.span_id or dd.trace_id
+            // Scope: N/A
+            // Custom property: N/A
+            logString = filteredLogs[logIndex++];
+            Assert.DoesNotContain($"\"{CorrelationIdentifier.SpanIdKey}\"", logString);
+            Assert.DoesNotContain($"\"{CorrelationIdentifier.TraceIdKey}\"", logString);
+            Assert.DoesNotContain($"\"{LoggingProviderTestHelpers.CustomPropertyName}\"", logString);
+
             // Scope: Parent scope
             // Custom property: N/A
             logString = filteredLogs[logIndex++];
@@ -126,6 +134,13 @@ public void DisabledLibLogSubscriberDoesNotAddTraceData()
             Assert.DoesNotContain($"\"{CorrelationIdentifier.TraceIdKey}\"", logString);
             Assert.DoesNotContain($"\"{LoggingProviderTestHelpers.CustomPropertyName}\"", logString);
 
+            // Scope: N/A
+            // Custom property: N/A
+            logString = filteredLogs[logIndex++];
+            Assert.DoesNotContain($"\"{CorrelationIdentifier.SpanIdKey}\"", logString);
+            Assert.DoesNotContain($"\"{CorrelationIdentifier.TraceIdKey}\"", logString);
+            Assert.DoesNotContain($"\"{LoggingProviderTestHelpers.CustomPropertyName}\"", logString);
+
             // Scope: N/A
             // Custom property: SET
             logString = filteredLogs[logIndex++];

test/Datadog.Trace.Tests/Logging/SerilogLogProviderTests.cs

@@ -44,6 +44,14 @@ public void EnabledLibLogSubscriberAddsTraceData()
             var logIndex = 0;
             LogEvent logEvent;
 
+            // The first log should not have dd.span_id or dd.trace_id
+            // Scope: N/A
+            // Custom property: N/A
+            logEvent = _logEvents[logIndex++];
+            Assert.False(logEvent.Properties.ContainsKey(CorrelationIdentifier.SpanIdKey));
+            Assert.False(logEvent.Properties.ContainsKey(CorrelationIdentifier.TraceIdKey));
+            Assert.False(logEvent.Properties.ContainsKey(LoggingProviderTestHelpers.CustomPropertyName));
+
             // Scope: Parent scope
             // Custom property: N/A
             logEvent = _logEvents[logIndex++];
@@ -108,6 +116,13 @@ public void DisabledLibLogSubscriberDoesNotAddTraceData()
             Assert.False(logEvent.Properties.ContainsKey(CorrelationIdentifier.TraceIdKey));
             Assert.False(logEvent.Properties.ContainsKey(LoggingProviderTestHelpers.CustomPropertyName));
 
+            // Scope: N/A
+            // Custom property: N/A
+            logEvent = _logEvents[logIndex++];
+            Assert.False(logEvent.Properties.ContainsKey(CorrelationIdentifier.SpanIdKey));
+            Assert.False(logEvent.Properties.ContainsKey(CorrelationIdentifier.TraceIdKey));
+            Assert.False(logEvent.Properties.ContainsKey(LoggingProviderTestHelpers.CustomPropertyName));
+
             // Scope: N/A
             // Custom property: SET
             logEvent = _logEvents[logIndex++];