Fix logging integration #500
Conversation
Codecov Report
@@ Coverage Diff @@
## master #500 +/- ##
============================================
- Coverage 66.01% 64.68% -1.33%
Complexity 68 68
============================================
Files 174 168 -6
Lines 7176 6425 -751
Branches 868 748 -120
============================================
- Hits 4737 4156 -581
+ Misses 2151 2007 -144
+ Partials 288 262 -26
Continue to review full report at Codecov.
|
| public void onDeactivate() throws Throwable { | ||
| if (config != null && config.isLogCorrelationEnabled()) { | ||
| MethodHandle remove = mdcRemoveMethodHandleCache.get(Thread.currentThread().getContextClassLoader()); | ||
| public void onDeactivate(TraceContextHolder<?> context) throws Throwable { |
There was a problem hiding this comment.
We can't add the TraceContextHolder here as it might already be ended and recycled.
There was a problem hiding this comment.
This method is called from TraceContextHolder#deactivate, when the this instance is still the active one on the thread stack, so I it is very valid to for checking this state. You are right however that I shouldn't observe it, so I shouldn't call isSampled for example.
So, I will add to documentation that I can only use the reference but not observe and certainly not update its state
There was a problem hiding this comment.
Another option is to transfer on the TraceContextHolder instance hash code...
There was a problem hiding this comment.
You are right however that I shouldn't observe it, so I shouldn't call
isSampledfor example.
By providing the context as an argument, we are more likely to make mistakes as that. We should only add the argument if the need for it actually arises. Even then it might more sense to just have the identity hash as a parameter.
| MethodHandle remove = mdcRemoveMethodHandleCache.get(Thread.currentThread().getContextClassLoader()); | ||
| public void onDeactivate(TraceContextHolder<?> context) throws Throwable { | ||
| if (config != null && config.isLogCorrelationEnabled() && context.isSampled()) { | ||
| String formerSpanId = spanIdStack.get().poll(); |
There was a problem hiding this comment.
Instead of maintaining another stack here, couldn't we just get tracer.getActive() and call isSampled() and traceContext.getId().toString() on that instance?
There was a problem hiding this comment.
This contradicts what you mentioned in the above comment :)
It may be already ended and recycled, so not allowed to observe at this point.
There was a problem hiding this comment.
What I meant was to get the parent of the context which is being deactivated. You reversed the order in the PR so that it deactivates after calling the listeners. I think we should make it more obvious from the method name if the deactivation happens before or after. For example we should call it either beforeDeactivate or afterDeactivate.
There was a problem hiding this comment.
Ahh, I see.
To me, the right way to undo/reverse A -> B -> C -> D is !D -> !C -> !B -> !A. So, for this matter, if A is TraceContextHolder#activate and B is ActivationListener#onActivate, It seemed to make sense to reverse the order.
What if I change ActivationListener#onActivate to beforeActivate and ActivationListener#onDeactivate to afterDeactivate? Then I can remove the additional stack as you suggest and have consistent code in both methods:
public void beforeActivate(TraceContextHolder<?> context) throws Throwable {
...
if (tracer != null) {
if (tracer.getActive() == null) {
put.invokeExact(TRACE_ID, traceContext.getTraceId().toString());
put.invokeExact(TRANSACTION_ID, traceContext.getTransactionId().toString());
}
put.invokeExact(SPAN_ID, traceContext.getId().toString());
}
}
public void afterDeactivate(TraceContextHolder<?> context) throws Throwable {
...
if (tracer != null) {
TraceContextHolder active = tracer.getActive();
if (active == null) {
remove.invokeExact(TRACE_ID);
remove.invokeExact(TRANSACTION_ID);
} else if (active.isSampled()) {
put.invokeExact(SPAN_ID, active.getTraceContext().getId().toString());
}
}
}
|
We decided to:
|
Fixes #499 and also enables proper logging integration for async spans/transactions as well.
In the sake of simplification, I added a
span.idin all cases (even from transactions), so ID will be duplicated in logs created when the active context is a transaction. This means that log lines will be consistent for all types, so aggregations done forspan.idwill include transaction-related events as well. We need to decide whether this is a good thing (supports aggregations for all spans AND transactions easily) or a bad thing (doesn't support aggregations for spans AND NOT transactions).