Skip to content

Commit

Permalink
Fix issue with auto-injection of Correlation Identifiers (Serilog) (D…
Browse files Browse the repository at this point in the history 
…ataDog#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.
  • Loading branch information
@zacharycmontoya
zacharycmontoya authored Aug 16, 2019
1 parent c018777 commit efe193e
Show file tree
Hide file tree
Showing 7 changed files with 365 additions and 122 deletions.
3 changes: 1 addition & 2 deletions reproductions/DataDogThreadTest/Program.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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}");
}
Expand Down
7 changes: 4 additions & 3 deletions src/Datadog.Trace/AsyncLocalScopeManager.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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));
Expand Down
97 changes: 78 additions & 19 deletions src/Datadog.Trace/Logging/LibLogScopeEventSubscriber.cs
View file
Original file line number Diff line number Diff line change
@@ -1,62 +1,121 @@
using System;
using System.Collections.Concurrent;
using System.Collections.Generic;
using System.Diagnostics;
using Datadog.Trace.Logging.LogProviders;

namespace Datadog.Trace.Logging
{
/// <summary>
/// Subscriber to ScopeManager events that sets/unsets correlation identifier
/// properties in the application's logging context.
/// </summary>
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<IDisposable> _contextDisposalStack = new ConcurrentStack<IDisposable>();

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))
{
ctxDisposable.Dispose();
}
}

private void SetLoggingValues(ulong traceId, ulong spanId)
private void SetCorrelationIdentifierContext(ulong traceId, ulong spanId)
{
_contextDisposalStack.Push(
LogProvider.OpenMappedContext(
Expand Down
130 changes: 88 additions & 42 deletions test/Datadog.Trace.Tests/Logging/Log4NetLogProviderTests.cs
View file
Original file line number Diff line number Diff line change
@@ -1,3 +1,4 @@
using System.Collections.Generic;
using System.Reflection;
using Datadog.Trace.Logging;
using Datadog.Trace.Logging.LogProviders;
Expand All @@ -11,17 +12,19 @@ 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()
{
_memoryAppender = new MemoryAppender();
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]
Expand All @@ -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<LoggingEvent> filteredLogs = new List<LoggingEvent>(_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<ulong>(parentScope.Span.SpanId, ulong.Parse(logEvent.Properties[CorrelationIdentifier.SpanIdKey].ToString()));
Assert.Contains(CorrelationIdentifier.TraceIdKey, logEvent.Properties.GetKeys());
Assert.Equal<ulong>(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<ulong>(childScope.Span.SpanId, ulong.Parse(logEvent.Properties[CorrelationIdentifier.SpanIdKey].ToString()));
Assert.Contains(CorrelationIdentifier.TraceIdKey, logEvent.Properties.GetKeys());
Assert.Equal<ulong>(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<ulong>(parentScope.Span.SpanId, ulong.Parse(logEvent.Properties[CorrelationIdentifier.SpanIdKey].ToString()));
Assert.Contains(CorrelationIdentifier.TraceIdKey, logEvent.Properties.GetKeys());
Assert.Equal<ulong>(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<ulong>(0, ulong.Parse(logEvent.Properties[CorrelationIdentifier.SpanIdKey].ToString()));
Assert.Contains(CorrelationIdentifier.TraceIdKey, logEvent.Properties.GetKeys());
Assert.Equal<ulong>(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<int>(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<int>(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<int>(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]
Expand All @@ -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<LoggingEvent> filteredLogs = new List<LoggingEvent>(_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<int>(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<int>(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<int>(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());
}
}
}
Loading

0 comments on commit efe193e

Please sign in to comment.