Fix issue with auto-injection of Correlation Identifiers (Serilog) #472
Conversation
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 all logging libraries, do not set initial values (dd.trace_id=0, dd.span_id=0). For Serilog, add and remove the two properties on SpanOpened and on SpanClosed. This ensures that properties only get added to/removed from the stack once.
zacharycmontoya
added
the
area:tracer
|
Is it still theoretically possible for this to happen if they add correlation properties after we open a scope and then they dispose of them after we have closed a scope? |
| 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); |
There was a problem hiding this comment.
Why the change to scope here?
There was a problem hiding this comment.
At this point we know that scope==current, and I wanted to have consistency in the variable name we used to make it easier to read. Everywhere we create an SpanEventArgs we use scope now so it seemed like a nice refactor.
…ing mapped contexts.
|
Serilog users should already be aware that they need to open and close their mapped contexts in the correct order, so they will likely be using |
…ace logging event.
…log4net. Also tidy up the LogProvider unit tests.
|
Colin and I chatted offline and realized that it will be really hard to ensure Serilog users don't get messed up. This PR is without a doubt an improvement because we only push/pop the correlation identifier properties when we open/close a span. While the other loggers will have a default value of 0, I've opted to not have a default value for Serilog because we would need some part of the managed profiler to inject the value early enough so as not to invalidate its stack behavior. |
… all loggers except Serilog.
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 (using Serilog) 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 all logging libraries, do not set initial values
(dd.trace_id=0, dd.span_id=0). For Serilog, add and remove the two
properties on SpanOpened and on SpanClosed. This ensures that properties
only get added to/removed from the stack once.
@DataDog/apm-dotnet