From efe193ec4c9f788190e19879ea9f1d943d7cf745 Mon Sep 17 00:00:00 2001 From: Zach Montoya Date: Fri, 16 Aug 2019 11:43:30 -0700 Subject: [PATCH] Fix issue with auto-injection of Correlation Identifiers (Serilog) (#472) Scenario: Some time after the first span is activated, we have set the logging context properties dd.trace_id=0 and dd.span_id=0. Application code then sets their own logging context properties. Then, a new span is created and previously-set properties no longer exist in the logging context. Problem: Our OnSpanActivated event immediately disposes the previously-set correlation identifier properties before re-adding the new values. Serilog has a strict correctness guarantee that requires properties be modified in stack order. Since we remove properties further down the stack, we end up losing properties. Fix: For Serilog, do not add efault values of TraceId=0 and SpanId=0. Also, add and remove the two properties on SpanOpened and on SpanClosed. This ensures that properties only get added to/removed from the stack once. --- reproductions/DataDogThreadTest/Program.cs | 3 +- src/Datadog.Trace/AsyncLocalScopeManager.cs | 7 +- .../Logging/LibLogScopeEventSubscriber.cs | 97 ++++++++++--- .../Logging/Log4NetLogProviderTests.cs | 130 ++++++++++++------ .../Logging/LoggingProviderTestHelpers.cs | 50 ++++++- .../Logging/NLogLogProviderTests.cs | 97 ++++++++++--- .../Logging/SerilogLogProviderTests.cs | 103 ++++++++++---- 7 files changed, 365 insertions(+), 122 deletions(-) diff --git a/reproductions/DataDogThreadTest/Program.cs b/reproductions/DataDogThreadTest/Program.cs index bbd18887a2a1..69f9ce09c234 100644 --- a/reproductions/DataDogThreadTest/Program.cs +++ b/reproductions/DataDogThreadTest/Program.cs @@ -142,12 +142,11 @@ static int Main(string[] args) logger.Info(NonTraceMessage); var lastLog = RelevantLogs().Last(); - var expectedOutOfTraceLog = "TraceId: 0, SpanId: 0"; var lastLogTraceId = lastLog.Properties[TraceIdKey]; var lastLogSpanIdId = lastLog.Properties[SpanIdKey]; var actual = $"TraceId: {lastLogTraceId}, SpanId: {lastLogSpanIdId}"; - if (!actual.Equals(expectedOutOfTraceLog)) + if (!actual.Equals(NonTraceMessage)) { throw new Exception($"Unexpected TraceId or SpanId: {actual}"); } diff --git a/src/Datadog.Trace/AsyncLocalScopeManager.cs b/src/Datadog.Trace/AsyncLocalScopeManager.cs index 724c1adf528a..a275f5d86f5d 100644 --- a/src/Datadog.Trace/AsyncLocalScopeManager.cs +++ b/src/Datadog.Trace/AsyncLocalScopeManager.cs @@ -49,17 +49,18 @@ public void Close(Scope scope) if (current == null || current != scope) { // This is not the current scope for this context, bail out + SpanClosed?.Invoke(this, new SpanEventArgs(scope.Span)); return; } // if the scope that was just closed was the active scope, // set its parent as the new active scope - _activeScope.Set(current.Parent); - SpanDeactivated?.Invoke(this, new SpanEventArgs(current.Span)); + _activeScope.Set(scope.Parent); + SpanDeactivated?.Invoke(this, new SpanEventArgs(scope.Span)); if (!isRootSpan) { - SpanActivated?.Invoke(this, new SpanEventArgs(current.Parent.Span)); + SpanActivated?.Invoke(this, new SpanEventArgs(scope.Parent.Span)); } SpanClosed?.Invoke(this, new SpanEventArgs(scope.Span)); diff --git a/src/Datadog.Trace/Logging/LibLogScopeEventSubscriber.cs b/src/Datadog.Trace/Logging/LibLogScopeEventSubscriber.cs index 5acd1bacbea6..79f15dc29bca 100644 --- a/src/Datadog.Trace/Logging/LibLogScopeEventSubscriber.cs +++ b/src/Datadog.Trace/Logging/LibLogScopeEventSubscriber.cs @@ -1,54 +1,113 @@ using System; using System.Collections.Concurrent; +using System.Collections.Generic; +using System.Diagnostics; +using Datadog.Trace.Logging.LogProviders; namespace Datadog.Trace.Logging { + /// + /// Subscriber to ScopeManager events that sets/unsets correlation identifier + /// properties in the application's logging context. + /// internal class LibLogScopeEventSubscriber : IDisposable { private readonly IScopeManager _scopeManager; + private readonly ILogProvider _logProvider; // Each mapped context sets a key-value pair into the logging context - // Disposing the context unsets the key-value pair + // Disposing the returned context unsets the key-value pair + // Keep a stack to retain the history of our correlation identifier properties + // (the stack is particularly important for Serilog, see below). // - // IMPORTANT: The contexts must be closed in reverse-order of opening, - // so by convention always open the TraceId context before - // opening the SpanId context, and close the contexts in - // the opposite order + // 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. private readonly ConcurrentStack _contextDisposalStack = new ConcurrentStack(); public LibLogScopeEventSubscriber(IScopeManager scopeManager) { _scopeManager = scopeManager; - _scopeManager.SpanActivated += OnSpanActivated; - _scopeManager.TraceEnded += OnTraceEnded; - SetDefaultValues(); + + _logProvider = LogProvider.CurrentLogProvider ?? LogProvider.ResolveLogProvider(); + if (_logProvider is SerilogLogProvider) + { + // Do not set default values for Serilog because it is unsafe to set + // except at the application startup, but this would require auto-instrumentation + _scopeManager.SpanOpened += StackOnSpanOpened; + _scopeManager.SpanClosed += StackOnSpanClosed; + } + else + { + SetDefaultValues(); + _scopeManager.SpanActivated += MapOnSpanActivated; + _scopeManager.TraceEnded += MapOnTraceEnded; + } + } + + public void StackOnSpanOpened(object sender, SpanEventArgs spanEventArgs) + { + SetCorrelationIdentifierContext(spanEventArgs.Span.TraceId, spanEventArgs.Span.SpanId); + } + + public void StackOnSpanClosed(object sender, SpanEventArgs spanEventArgs) + { + RemoveLastCorrelationIdentifierContext(); } - public void OnSpanActivated(object sender, SpanEventArgs spanEventArgs) + public void MapOnSpanActivated(object sender, SpanEventArgs spanEventArgs) { - DisposeAll(); - SetLoggingValues(spanEventArgs.Span.TraceId, spanEventArgs.Span.SpanId); + RemoveAllCorrelationIdentifierContexts(); + SetCorrelationIdentifierContext(spanEventArgs.Span.TraceId, spanEventArgs.Span.SpanId); } - public void OnTraceEnded(object sender, SpanEventArgs spanEventArgs) + public void MapOnTraceEnded(object sender, SpanEventArgs spanEventArgs) { - DisposeAll(); + RemoveAllCorrelationIdentifierContexts(); SetDefaultValues(); } public void Dispose() { - _scopeManager.SpanActivated -= OnSpanActivated; - _scopeManager.TraceEnded -= OnTraceEnded; - DisposeAll(); + if (_logProvider is SerilogLogProvider) + { + _scopeManager.SpanOpened -= StackOnSpanOpened; + _scopeManager.SpanClosed -= StackOnSpanClosed; + } + else + { + _scopeManager.SpanActivated -= MapOnSpanActivated; + _scopeManager.TraceEnded -= MapOnTraceEnded; + } + + RemoveAllCorrelationIdentifierContexts(); } private void SetDefaultValues() { - SetLoggingValues(0, 0); + SetCorrelationIdentifierContext(0, 0); + } + + private void RemoveLastCorrelationIdentifierContext() + { + for (int i = 0; i < 2; i++) + { + if (_contextDisposalStack.TryPop(out IDisposable ctxDisposable)) + { + ctxDisposable.Dispose(); + } + else + { + // There is nothing left to pop so do nothing. + // Though we are in a strange circumstance if we did not balance + // the stack properly + Debug.Fail($"{nameof(RemoveLastCorrelationIdentifierContext)} call failed. Too few items on the context stack."); + } + } } - private void DisposeAll() + private void RemoveAllCorrelationIdentifierContexts() { while (_contextDisposalStack.TryPop(out IDisposable ctxDisposable)) { @@ -56,7 +115,7 @@ private void DisposeAll() } } - private void SetLoggingValues(ulong traceId, ulong spanId) + private void SetCorrelationIdentifierContext(ulong traceId, ulong spanId) { _contextDisposalStack.Push( LogProvider.OpenMappedContext( diff --git a/test/Datadog.Trace.Tests/Logging/Log4NetLogProviderTests.cs b/test/Datadog.Trace.Tests/Logging/Log4NetLogProviderTests.cs index c7d76bbc2894..657510bd0305 100644 --- a/test/Datadog.Trace.Tests/Logging/Log4NetLogProviderTests.cs +++ b/test/Datadog.Trace.Tests/Logging/Log4NetLogProviderTests.cs @@ -1,3 +1,4 @@ +using System.Collections.Generic; using System.Reflection; using Datadog.Trace.Logging; using Datadog.Trace.Logging.LogProviders; @@ -11,8 +12,9 @@ namespace Datadog.Trace.Tests.Logging [Collection(nameof(Datadog.Trace.Tests.Logging))] public class Log4NetLogProviderTests { + private readonly ILogProvider _logProvider; + private readonly ILog _logger; private readonly MemoryAppender _memoryAppender; - private ILog _logger; public Log4NetLogProviderTests() { @@ -20,8 +22,9 @@ public Log4NetLogProviderTests() var repository = log4net.LogManager.GetRepository(Assembly.GetAssembly(typeof(log4net.LogManager))); BasicConfigurator.Configure(repository, _memoryAppender); - LogProvider.SetCurrentLogProvider(new Log4NetLogProvider()); - _logger = LogProvider.GetLogger(typeof(Log4NetLogProviderTests)); + _logProvider = new Log4NetLogProvider(); + LogProvider.SetCurrentLogProvider(_logProvider); + _logger = new LoggerExecutionWrapper(_logProvider.GetLogger("Test")); } [Fact] @@ -32,39 +35,54 @@ public void EnabledLibLogSubscriberAddsTraceData() // Instantiate a tracer for this test with default settings and set LogsInjectionEnabled to TRUE var tracer = LoggingProviderTestHelpers.InitializeTracer(enableLogsInjection: true); - LoggingProviderTestHelpers.PerformParentChildScopeSequence(tracer, _logger, out var parentScope, out var childScope); + LoggingProviderTestHelpers.PerformParentChildScopeSequence(tracer, _logger, _logProvider.OpenMappedContext, out var parentScope, out var childScope); + + // Filter the logs + List filteredLogs = new List(_memoryAppender.GetEvents()); + filteredLogs.RemoveAll(log => !log.MessageObject.ToString().Contains(LoggingProviderTestHelpers.LogPrefix)); int logIndex = 0; - var logEvents = _memoryAppender.GetEvents(); LoggingEvent logEvent; - // Verify the log event is decorated with the parent scope properties - logEvent = logEvents[logIndex++]; - Assert.Contains(CorrelationIdentifier.SpanIdKey, logEvent.Properties.GetKeys()); - Assert.Equal(parentScope.Span.SpanId, ulong.Parse(logEvent.Properties[CorrelationIdentifier.SpanIdKey].ToString())); - Assert.Contains(CorrelationIdentifier.TraceIdKey, logEvent.Properties.GetKeys()); - Assert.Equal(parentScope.Span.TraceId, ulong.Parse(logEvent.Properties[CorrelationIdentifier.TraceIdKey].ToString())); - - // Verify the log event is decorated with the child scope properties - logEvent = logEvents[logIndex++]; - Assert.Contains(CorrelationIdentifier.SpanIdKey, logEvent.Properties.GetKeys()); - Assert.Equal(childScope.Span.SpanId, ulong.Parse(logEvent.Properties[CorrelationIdentifier.SpanIdKey].ToString())); - Assert.Contains(CorrelationIdentifier.TraceIdKey, logEvent.Properties.GetKeys()); - Assert.Equal(childScope.Span.TraceId, ulong.Parse(logEvent.Properties[CorrelationIdentifier.TraceIdKey].ToString())); - - // Verify the log event is decorated with the parent scope properties - logEvent = logEvents[logIndex++]; - Assert.Contains(CorrelationIdentifier.SpanIdKey, logEvent.Properties.GetKeys()); - Assert.Equal(parentScope.Span.SpanId, ulong.Parse(logEvent.Properties[CorrelationIdentifier.SpanIdKey].ToString())); - Assert.Contains(CorrelationIdentifier.TraceIdKey, logEvent.Properties.GetKeys()); - Assert.Equal(parentScope.Span.TraceId, ulong.Parse(logEvent.Properties[CorrelationIdentifier.TraceIdKey].ToString())); - - // Verify the log event is decorated with zero values - logEvent = logEvents[logIndex++]; - Assert.Contains(CorrelationIdentifier.SpanIdKey, logEvent.Properties.GetKeys()); - Assert.Equal(0, ulong.Parse(logEvent.Properties[CorrelationIdentifier.SpanIdKey].ToString())); - Assert.Contains(CorrelationIdentifier.TraceIdKey, logEvent.Properties.GetKeys()); - Assert.Equal(0, ulong.Parse(logEvent.Properties[CorrelationIdentifier.TraceIdKey].ToString())); + // Scope: Parent scope + // Custom property: N/A + logEvent = filteredLogs[logIndex++]; + logEvent.Contains(parentScope); + Assert.DoesNotContain(LoggingProviderTestHelpers.CustomPropertyName, logEvent.Properties.GetKeys()); + + // Scope: Parent scope + // Custom property: SET + logEvent = filteredLogs[logIndex++]; + logEvent.Contains(parentScope); + Assert.Contains(LoggingProviderTestHelpers.CustomPropertyName, logEvent.Properties.GetKeys()); + Assert.Equal(LoggingProviderTestHelpers.CustomPropertyValue, int.Parse(logEvent.Properties[LoggingProviderTestHelpers.CustomPropertyName].ToString())); + + // Scope: Child scope + // Custom property: SET + logEvent = filteredLogs[logIndex++]; + logEvent.Contains(childScope); + Assert.Contains(LoggingProviderTestHelpers.CustomPropertyName, logEvent.Properties.GetKeys()); + Assert.Equal(LoggingProviderTestHelpers.CustomPropertyValue, int.Parse(logEvent.Properties[LoggingProviderTestHelpers.CustomPropertyName].ToString())); + + // Scope: Parent scope + // Custom property: SET + logEvent = filteredLogs[logIndex++]; + logEvent.Contains(parentScope); + Assert.Contains(LoggingProviderTestHelpers.CustomPropertyName, logEvent.Properties.GetKeys()); + Assert.Equal(LoggingProviderTestHelpers.CustomPropertyValue, int.Parse(logEvent.Properties[LoggingProviderTestHelpers.CustomPropertyName].ToString())); + + // EXISTING: Verify the log event is decorated with the parent scope properties + // Scope: Parent scope + // Custom property: N/A + logEvent = filteredLogs[logIndex++]; + logEvent.Contains(parentScope); + Assert.DoesNotContain(LoggingProviderTestHelpers.CustomPropertyName, logEvent.Properties.GetKeys()); + + // Scope: Default values of TraceId=0,SpanId=0 + // Custom property: N/A + logEvent = filteredLogs[logIndex++]; + logEvent.Contains(traceId: 0, spanId: 0); + Assert.DoesNotContain(LoggingProviderTestHelpers.CustomPropertyName, logEvent.Properties.GetKeys()); } [Fact] @@ -75,31 +93,59 @@ public void DisabledLibLogSubscriberDoesNotAddTraceData() // Instantiate a tracer for this test with default settings and set LogsInjectionEnabled to TRUE var tracer = LoggingProviderTestHelpers.InitializeTracer(enableLogsInjection: false); - LoggingProviderTestHelpers.PerformParentChildScopeSequence(tracer, _logger, out var parentScope, out var childScope); + LoggingProviderTestHelpers.PerformParentChildScopeSequence(tracer, _logger, _logProvider.OpenMappedContext, out var parentScope, out var childScope); + + // Filter the logs + List filteredLogs = new List(_memoryAppender.GetEvents()); + filteredLogs.RemoveAll(log => !log.MessageObject.ToString().Contains(LoggingProviderTestHelpers.LogPrefix)); int logIndex = 0; - var logEvents = _memoryAppender.GetEvents(); LoggingEvent logEvent; - // Verify the log event is not decorated with the properties - logEvent = logEvents[logIndex++]; + // 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++]; + Assert.DoesNotContain(CorrelationIdentifier.SpanIdKey, logEvent.Properties.GetKeys()); + Assert.DoesNotContain(CorrelationIdentifier.TraceIdKey, logEvent.Properties.GetKeys()); + Assert.Contains(LoggingProviderTestHelpers.CustomPropertyName, logEvent.Properties.GetKeys()); + Assert.Equal(LoggingProviderTestHelpers.CustomPropertyValue, int.Parse(logEvent.Properties[LoggingProviderTestHelpers.CustomPropertyName].ToString())); + + // Scope: N/A + // Custom property: SET + logEvent = filteredLogs[logIndex++]; Assert.DoesNotContain(CorrelationIdentifier.SpanIdKey, logEvent.Properties.GetKeys()); Assert.DoesNotContain(CorrelationIdentifier.TraceIdKey, logEvent.Properties.GetKeys()); + Assert.Contains(LoggingProviderTestHelpers.CustomPropertyName, logEvent.Properties.GetKeys()); + Assert.Equal(LoggingProviderTestHelpers.CustomPropertyValue, int.Parse(logEvent.Properties[LoggingProviderTestHelpers.CustomPropertyName].ToString())); - // Verify the log event is not decorated with the properties - logEvent = logEvents[logIndex++]; + // Scope: N/A + // Custom property: SET + logEvent = filteredLogs[logIndex++]; Assert.DoesNotContain(CorrelationIdentifier.SpanIdKey, logEvent.Properties.GetKeys()); Assert.DoesNotContain(CorrelationIdentifier.TraceIdKey, logEvent.Properties.GetKeys()); + Assert.Contains(LoggingProviderTestHelpers.CustomPropertyName, logEvent.Properties.GetKeys()); + Assert.Equal(LoggingProviderTestHelpers.CustomPropertyValue, int.Parse(logEvent.Properties[LoggingProviderTestHelpers.CustomPropertyName].ToString())); - // Verify the log event is not decorated with the properties - logEvent = logEvents[logIndex++]; + // 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()); - // Verify the log event is not decorated with the properties - logEvent = logEvents[logIndex++]; + // 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()); } } } diff --git a/test/Datadog.Trace.Tests/Logging/LoggingProviderTestHelpers.cs b/test/Datadog.Trace.Tests/Logging/LoggingProviderTestHelpers.cs index 6042511bef01..55e4f088ba9d 100644 --- a/test/Datadog.Trace.Tests/Logging/LoggingProviderTestHelpers.cs +++ b/test/Datadog.Trace.Tests/Logging/LoggingProviderTestHelpers.cs @@ -1,13 +1,19 @@ +using System; using Datadog.Trace.Agent; using Datadog.Trace.Configuration; using Datadog.Trace.Logging; using Datadog.Trace.Sampling; using Moq; +using Xunit; namespace Datadog.Trace.Tests.Logging { - internal class LoggingProviderTestHelpers + internal static class LoggingProviderTestHelpers { + internal static readonly string CustomPropertyName = "custom"; + internal static readonly int CustomPropertyValue = 1; + internal static readonly string LogPrefix = "[Datadog.Trace.Tests.Logging]"; + internal static Tracer InitializeTracer(bool enableLogsInjection) { var settings = new TracerSettings(); @@ -19,19 +25,51 @@ internal static Tracer InitializeTracer(bool enableLogsInjection) return new Tracer(settings, writerMock.Object, samplerMock.Object, null); } - internal static void PerformParentChildScopeSequence(Tracer tracer, ILog logger, out Scope parentScope, out Scope childScope) + internal static void PerformParentChildScopeSequence(Tracer tracer, ILog logger, Func openMappedContext, out Scope parentScope, out Scope childScope) { parentScope = tracer.StartActive("parent"); - logger.Log(LogLevel.Info, () => "Started and activated parent scope."); + logger.Log(LogLevel.Info, () => $"{LogPrefix}Started and activated parent scope."); + + var customPropertyContext = openMappedContext(CustomPropertyName, CustomPropertyValue, false); + logger.Log(LogLevel.Info, () => $"{LogPrefix}Added custom property to MDC"); childScope = tracer.StartActive("child"); - logger.Log(LogLevel.Info, () => "Started and activated child scope."); + logger.Log(LogLevel.Info, () => $"{LogPrefix}Started and activated child scope."); childScope.Close(); - logger.Log(LogLevel.Info, () => "Closed child scope and reactivated parent scope."); + logger.Log(LogLevel.Info, () => $"{LogPrefix}Closed child scope and reactivated parent scope."); + + customPropertyContext.Dispose(); + logger.Log(LogLevel.Info, () => $"{LogPrefix}Removed custom property from MDC"); parentScope.Close(); - logger.Log(LogLevel.Info, () => "Closed child scope so there is no active scope."); + logger.Log(LogLevel.Info, () => $"{LogPrefix}Closed child scope so there is no active scope."); + } + + internal static void Contains(this log4net.Core.LoggingEvent logEvent, Scope scope) + { + logEvent.Contains(scope.Span.TraceId, scope.Span.SpanId); + } + + internal static void Contains(this log4net.Core.LoggingEvent logEvent, ulong traceId, ulong spanId) + { + Assert.Contains(CorrelationIdentifier.TraceIdKey, logEvent.Properties.GetKeys()); + Assert.Equal(traceId, ulong.Parse(logEvent.Properties[CorrelationIdentifier.TraceIdKey].ToString())); + Assert.Contains(CorrelationIdentifier.SpanIdKey, logEvent.Properties.GetKeys()); + Assert.Equal(spanId, ulong.Parse(logEvent.Properties[CorrelationIdentifier.SpanIdKey].ToString())); + } + + internal static void Contains(this Serilog.Events.LogEvent logEvent, Scope scope) + { + logEvent.Contains(scope.Span.TraceId, scope.Span.SpanId); + } + + internal static void Contains(this Serilog.Events.LogEvent logEvent, ulong traceId, ulong spanId) + { + Assert.True(logEvent.Properties.ContainsKey(CorrelationIdentifier.TraceIdKey)); + Assert.Equal(traceId, ulong.Parse(logEvent.Properties[CorrelationIdentifier.TraceIdKey].ToString())); + Assert.True(logEvent.Properties.ContainsKey(CorrelationIdentifier.SpanIdKey)); + Assert.Equal(spanId, ulong.Parse(logEvent.Properties[CorrelationIdentifier.SpanIdKey].ToString())); } } } diff --git a/test/Datadog.Trace.Tests/Logging/NLogLogProviderTests.cs b/test/Datadog.Trace.Tests/Logging/NLogLogProviderTests.cs index a007c3a92b78..9a091db0ac02 100644 --- a/test/Datadog.Trace.Tests/Logging/NLogLogProviderTests.cs +++ b/test/Datadog.Trace.Tests/Logging/NLogLogProviderTests.cs @@ -1,3 +1,4 @@ +using System.Collections.Generic; using Datadog.Trace.Logging; using Datadog.Trace.Logging.LogProviders; using NLog; @@ -10,6 +11,7 @@ namespace Datadog.Trace.Tests.Logging [Collection(nameof(Datadog.Trace.Tests.Logging))] public class NLogLogProviderTests { + private readonly ILogProvider _logProvider; private readonly ILog _logger; private readonly MemoryTarget _target; @@ -18,7 +20,7 @@ public NLogLogProviderTests() var config = new LoggingConfiguration(); _target = new MemoryTarget { - Layout = string.Format("${{level:uppercase=true}}|{0}=${{mdc:item={0}}}|{1}=${{mdc:item={1}}}|${{message}}", CorrelationIdentifier.SpanIdKey, CorrelationIdentifier.TraceIdKey) + Layout = string.Format("${{level:uppercase=true}}|{0}=${{mdc:item={0}}}|{1}=${{mdc:item={1}}}|{2}=${{mdc:item={2}}}|${{message}}", CorrelationIdentifier.SpanIdKey, CorrelationIdentifier.TraceIdKey, LoggingProviderTestHelpers.CustomPropertyName) }; config.AddTarget("memory", _target); @@ -26,8 +28,9 @@ public NLogLogProviderTests() LogManager.Configuration = config; SimpleConfigurator.ConfigureForTargetLogging(_target, NLog.LogLevel.Trace); - LogProvider.SetCurrentLogProvider(new NLogLogProvider()); - _logger = LogProvider.GetLogger(typeof(NLogLogProviderTests)); + _logProvider = new NLogLogProvider(); + LogProvider.SetCurrentLogProvider(_logProvider); + _logger = new LoggerExecutionWrapper(_logProvider.GetLogger("test")); } [Fact] @@ -38,30 +41,56 @@ public void EnabledLibLogSubscriberAddsTraceData() // Instantiate a tracer for this test with default settings and set LogsInjectionEnabled to TRUE var tracer = LoggingProviderTestHelpers.InitializeTracer(enableLogsInjection: true); - LoggingProviderTestHelpers.PerformParentChildScopeSequence(tracer, _logger, out var parentScope, out var childScope); + LoggingProviderTestHelpers.PerformParentChildScopeSequence(tracer, _logger, _logProvider.OpenMappedContext, out var parentScope, out var childScope); + + // Filter the logs + List filteredLogs = new List(_target.Logs); + filteredLogs.RemoveAll(log => !log.Contains(LoggingProviderTestHelpers.LogPrefix)); int logIndex = 0; string logString; - // Verify the log event is decorated with the parent scope properties - logString = _target.Logs[logIndex++]; + // Scope: Parent scope + // Custom property: N/A + logString = filteredLogs[logIndex++]; + Assert.Contains($"{CorrelationIdentifier.SpanIdKey}={parentScope.Span.SpanId}", logString); + Assert.Contains($"{CorrelationIdentifier.TraceIdKey}={parentScope.Span.TraceId}", logString); + Assert.Contains($"{LoggingProviderTestHelpers.CustomPropertyName}=", logString); + + // Scope: Parent scope + // Custom property: SET + logString = filteredLogs[logIndex++]; Assert.Contains($"{CorrelationIdentifier.SpanIdKey}={parentScope.Span.SpanId}", logString); Assert.Contains($"{CorrelationIdentifier.TraceIdKey}={parentScope.Span.TraceId}", logString); + Assert.Contains($"{LoggingProviderTestHelpers.CustomPropertyName}={LoggingProviderTestHelpers.CustomPropertyValue}", logString); - // Verify the log event is decorated with the child scope properties - logString = _target.Logs[logIndex++]; + // Scope: Child scope + // Custom property: SET + logString = filteredLogs[logIndex++]; Assert.Contains($"{CorrelationIdentifier.SpanIdKey}={childScope.Span.SpanId}", logString); Assert.Contains($"{CorrelationIdentifier.TraceIdKey}={childScope.Span.TraceId}", logString); + Assert.Contains($"{LoggingProviderTestHelpers.CustomPropertyName}={LoggingProviderTestHelpers.CustomPropertyValue}", logString); + + // Scope: Parent scope + // Custom property: SET + logString = filteredLogs[logIndex++]; + Assert.Contains($"{CorrelationIdentifier.SpanIdKey}={parentScope.Span.SpanId}", logString); + Assert.Contains($"{CorrelationIdentifier.TraceIdKey}={parentScope.Span.TraceId}", logString); + Assert.Contains($"{LoggingProviderTestHelpers.CustomPropertyName}={LoggingProviderTestHelpers.CustomPropertyValue}", logString); - // Verify the log event is decorated with the parent scope properties - logString = _target.Logs[logIndex++]; + // Scope: Parent scope + // Custom property: N/A + logString = filteredLogs[logIndex++]; Assert.Contains($"{CorrelationIdentifier.SpanIdKey}={parentScope.Span.SpanId}", logString); Assert.Contains($"{CorrelationIdentifier.TraceIdKey}={parentScope.Span.TraceId}", logString); + Assert.Contains($"{LoggingProviderTestHelpers.CustomPropertyName}=", logString); - // Verify the log event is decorated with zero values - logString = _target.Logs[logIndex++]; + // Scope: Default values of TraceId=0,SpanId=0 + // Custom property: N/A + logString = filteredLogs[logIndex++]; Assert.Contains($"{CorrelationIdentifier.SpanIdKey}=0", logString); Assert.Contains($"{CorrelationIdentifier.TraceIdKey}=0", logString); + Assert.Contains($"{LoggingProviderTestHelpers.CustomPropertyName}=", logString); } [Fact] @@ -72,30 +101,56 @@ public void DisabledLibLogSubscriberDoesNotAddTraceData() // Instantiate a tracer for this test with default settings and set LogsInjectionEnabled to TRUE var tracer = LoggingProviderTestHelpers.InitializeTracer(enableLogsInjection: false); - LoggingProviderTestHelpers.PerformParentChildScopeSequence(tracer, _logger, out var parentScope, out var childScope); + LoggingProviderTestHelpers.PerformParentChildScopeSequence(tracer, _logger, _logProvider.OpenMappedContext, out var parentScope, out var childScope); + + // Filter the logs + List filteredLogs = new List(_target.Logs); + filteredLogs.RemoveAll(log => !log.Contains(LoggingProviderTestHelpers.LogPrefix)); int logIndex = 0; string logString; - // Verify the log event is not decorated with the properties - logString = _target.Logs[logIndex++]; + // Scope: N/A + // Custom property: N/A + logString = filteredLogs[logIndex++]; + Assert.Contains($"{CorrelationIdentifier.SpanIdKey}=", logString); + Assert.Contains($"{CorrelationIdentifier.TraceIdKey}=", logString); + Assert.Contains($"{LoggingProviderTestHelpers.CustomPropertyName}=", logString); + + // Scope: N/A + // Custom property: SET + logString = filteredLogs[logIndex++]; + Assert.Contains($"{CorrelationIdentifier.SpanIdKey}=", logString); + Assert.Contains($"{CorrelationIdentifier.TraceIdKey}=", logString); + Assert.Contains($"{LoggingProviderTestHelpers.CustomPropertyName}={LoggingProviderTestHelpers.CustomPropertyValue}", logString); + + // Scope: N/A + // Custom property: SET + logString = filteredLogs[logIndex++]; Assert.Contains($"{CorrelationIdentifier.SpanIdKey}=", logString); Assert.Contains($"{CorrelationIdentifier.TraceIdKey}=", logString); + Assert.Contains($"{LoggingProviderTestHelpers.CustomPropertyName}={LoggingProviderTestHelpers.CustomPropertyValue}", logString); - // Verify the log event is not decorated with the properties - logString = _target.Logs[logIndex++]; + // Scope: N/A + // Custom property: SET + logString = filteredLogs[logIndex++]; Assert.Contains($"{CorrelationIdentifier.SpanIdKey}=", logString); Assert.Contains($"{CorrelationIdentifier.TraceIdKey}=", logString); + Assert.Contains($"{LoggingProviderTestHelpers.CustomPropertyName}={LoggingProviderTestHelpers.CustomPropertyValue}", logString); - // Verify the log event is not decorated with the properties - logString = _target.Logs[logIndex++]; + // Scope: N/A + // Custom property: N/A + logString = filteredLogs[logIndex++]; Assert.Contains($"{CorrelationIdentifier.SpanIdKey}=", logString); Assert.Contains($"{CorrelationIdentifier.TraceIdKey}=", logString); + Assert.Contains($"{LoggingProviderTestHelpers.CustomPropertyName}=", logString); - // Verify the log event is not decorated with the properties - logString = _target.Logs[logIndex++]; + // Scope: N/A + // Custom property: N/A + logString = filteredLogs[logIndex++]; Assert.Contains($"{CorrelationIdentifier.SpanIdKey}=", logString); Assert.Contains($"{CorrelationIdentifier.TraceIdKey}=", logString); + Assert.Contains($"{LoggingProviderTestHelpers.CustomPropertyName}=", logString); } } } diff --git a/test/Datadog.Trace.Tests/Logging/SerilogLogProviderTests.cs b/test/Datadog.Trace.Tests/Logging/SerilogLogProviderTests.cs index d321378884d6..0ffae79f4c4a 100644 --- a/test/Datadog.Trace.Tests/Logging/SerilogLogProviderTests.cs +++ b/test/Datadog.Trace.Tests/Logging/SerilogLogProviderTests.cs @@ -11,6 +11,7 @@ namespace Datadog.Trace.Tests.Logging [Collection(nameof(Datadog.Trace.Tests.Logging))] public class SerilogLogProviderTests { + private readonly ILogProvider _logProvider; private readonly ILog _logger; private readonly List _logEvents; @@ -20,10 +21,11 @@ public SerilogLogProviderTests() .Enrich.FromLogContext() .WriteTo.Observers(obs => obs.Subscribe(logEvent => _logEvents.Add(logEvent))) .CreateLogger(); - - LogProvider.SetCurrentLogProvider(new SerilogLogProvider()); - _logger = LogProvider.GetLogger(typeof(SerilogLogProviderTests)); _logEvents = new List(); + + _logProvider = new SerilogLogProvider(); + LogProvider.SetCurrentLogProvider(_logProvider); + _logger = new LoggerExecutionWrapper(_logProvider.GetLogger("Test")); } [Fact] @@ -34,38 +36,53 @@ public void EnabledLibLogSubscriberAddsTraceData() // Instantiate a tracer for this test with default settings and set LogsInjectionEnabled to TRUE var tracer = LoggingProviderTestHelpers.InitializeTracer(enableLogsInjection: true); - LoggingProviderTestHelpers.PerformParentChildScopeSequence(tracer, _logger, out var parentScope, out var childScope); + LoggingProviderTestHelpers.PerformParentChildScopeSequence(tracer, _logger, _logProvider.OpenMappedContext, out var parentScope, out var childScope); + + // Filter the logs + _logEvents.RemoveAll(log => !log.MessageTemplate.ToString().Contains(LoggingProviderTestHelpers.LogPrefix)); var logIndex = 0; LogEvent logEvent; - // Verify the log event is decorated with the parent scope properties + // Scope: Parent scope + // Custom property: N/A + logEvent = _logEvents[logIndex++]; + logEvent.Contains(parentScope); + Assert.False(logEvent.Properties.ContainsKey(LoggingProviderTestHelpers.CustomPropertyName)); + + // Scope: Parent scope + // Custom property: SET logEvent = _logEvents[logIndex++]; - Assert.True(logEvent.Properties.ContainsKey(CorrelationIdentifier.SpanIdKey)); - Assert.Equal(parentScope.Span.SpanId, ulong.Parse(logEvent.Properties[CorrelationIdentifier.SpanIdKey].ToString())); - Assert.True(logEvent.Properties.ContainsKey(CorrelationIdentifier.TraceIdKey)); - Assert.Equal(parentScope.Span.TraceId, ulong.Parse(logEvent.Properties[CorrelationIdentifier.TraceIdKey].ToString())); + logEvent.Contains(parentScope); + Assert.True(logEvent.Properties.ContainsKey(LoggingProviderTestHelpers.CustomPropertyName)); + Assert.Equal(LoggingProviderTestHelpers.CustomPropertyValue, int.Parse(logEvent.Properties[LoggingProviderTestHelpers.CustomPropertyName].ToString())); - // Verify the log event is decorated with the child scope properties + // Scope: Child scope + // Custom property: SET logEvent = _logEvents[logIndex++]; - Assert.True(logEvent.Properties.ContainsKey(CorrelationIdentifier.SpanIdKey)); - Assert.Equal(childScope.Span.SpanId, ulong.Parse(logEvent.Properties[CorrelationIdentifier.SpanIdKey].ToString())); - Assert.True(logEvent.Properties.ContainsKey(CorrelationIdentifier.TraceIdKey)); - Assert.Equal(childScope.Span.TraceId, ulong.Parse(logEvent.Properties[CorrelationIdentifier.TraceIdKey].ToString())); + logEvent.Contains(childScope); + Assert.True(logEvent.Properties.ContainsKey(LoggingProviderTestHelpers.CustomPropertyName)); + Assert.Equal(LoggingProviderTestHelpers.CustomPropertyValue, int.Parse(logEvent.Properties[LoggingProviderTestHelpers.CustomPropertyName].ToString())); - // Verify the log event is decorated with the parent scope properties + // Scope: Parent scope + // Custom property: SET logEvent = _logEvents[logIndex++]; - Assert.True(logEvent.Properties.ContainsKey(CorrelationIdentifier.SpanIdKey)); - Assert.Equal(parentScope.Span.SpanId, ulong.Parse(logEvent.Properties[CorrelationIdentifier.SpanIdKey].ToString())); - Assert.True(logEvent.Properties.ContainsKey(CorrelationIdentifier.TraceIdKey)); - Assert.Equal(parentScope.Span.TraceId, ulong.Parse(logEvent.Properties[CorrelationIdentifier.TraceIdKey].ToString())); + logEvent.Contains(parentScope); + Assert.True(logEvent.Properties.ContainsKey(LoggingProviderTestHelpers.CustomPropertyName)); + Assert.Equal(LoggingProviderTestHelpers.CustomPropertyValue, int.Parse(logEvent.Properties[LoggingProviderTestHelpers.CustomPropertyName].ToString())); - // Verify the log event is decorated with zero values + // Scope: Parent scope + // Custom property: N/A logEvent = _logEvents[logIndex++]; - Assert.True(logEvent.Properties.ContainsKey(CorrelationIdentifier.SpanIdKey)); - Assert.Equal(0, ulong.Parse(logEvent.Properties[CorrelationIdentifier.SpanIdKey].ToString())); - Assert.True(logEvent.Properties.ContainsKey(CorrelationIdentifier.TraceIdKey)); - Assert.Equal(0, ulong.Parse(logEvent.Properties[CorrelationIdentifier.TraceIdKey].ToString())); + logEvent.Contains(parentScope); + 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)); } [Fact] @@ -76,30 +93,58 @@ public void DisabledLibLogSubscriberDoesNotAddTraceData() // Instantiate a tracer for this test with default settings and set LogsInjectionEnabled to TRUE var tracer = LoggingProviderTestHelpers.InitializeTracer(enableLogsInjection: false); - LoggingProviderTestHelpers.PerformParentChildScopeSequence(tracer, _logger, out var parentScope, out var childScope); + LoggingProviderTestHelpers.PerformParentChildScopeSequence(tracer, _logger, _logProvider.OpenMappedContext, out var parentScope, out var childScope); + + // Filter the logs + _logEvents.RemoveAll(log => !log.MessageTemplate.ToString().Contains(LoggingProviderTestHelpers.LogPrefix)); int logIndex = 0; LogEvent logEvent; - // Verify the log event is not decorated with the properties + // 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++]; + Assert.False(logEvent.Properties.ContainsKey(CorrelationIdentifier.SpanIdKey)); + Assert.False(logEvent.Properties.ContainsKey(CorrelationIdentifier.TraceIdKey)); + Assert.True(logEvent.Properties.ContainsKey(LoggingProviderTestHelpers.CustomPropertyName)); + Assert.Equal(LoggingProviderTestHelpers.CustomPropertyValue, int.Parse(logEvent.Properties[LoggingProviderTestHelpers.CustomPropertyName].ToString())); + + // Scope: N/A + // Custom property: SET logEvent = _logEvents[logIndex++]; Assert.False(logEvent.Properties.ContainsKey(CorrelationIdentifier.SpanIdKey)); Assert.False(logEvent.Properties.ContainsKey(CorrelationIdentifier.TraceIdKey)); + Assert.True(logEvent.Properties.ContainsKey(LoggingProviderTestHelpers.CustomPropertyName)); + Assert.Equal(LoggingProviderTestHelpers.CustomPropertyValue, int.Parse(logEvent.Properties[LoggingProviderTestHelpers.CustomPropertyName].ToString())); - // Verify the log event is not decorated with the properties + // Scope: N/A + // Custom property: SET logEvent = _logEvents[logIndex++]; Assert.False(logEvent.Properties.ContainsKey(CorrelationIdentifier.SpanIdKey)); Assert.False(logEvent.Properties.ContainsKey(CorrelationIdentifier.TraceIdKey)); + Assert.True(logEvent.Properties.ContainsKey(LoggingProviderTestHelpers.CustomPropertyName)); + Assert.Equal(LoggingProviderTestHelpers.CustomPropertyValue, int.Parse(logEvent.Properties[LoggingProviderTestHelpers.CustomPropertyName].ToString())); - // Verify the log event is not decorated with the properties + // 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)); - // Verify the log event is not decorated with the properties + // 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)); } } }