Introduce requestId MDC property #364
Conversation
JacekLach
force-pushed
the
jl/request-id
branch
from
cc0b0b8 to
68a90b4
Compare
Logs from concurrent incoming requests with the same traceid are currently difficult to tell apart (one can look at thread names etc, but not across executors). This introduces a new MDC property managed by Tracers, which stores a unique identifier when the top span of the current trace is a SERVER_INCOMING span.
JacekLach
force-pushed
the
jl/request-id
branch
from
68a90b4 to
5ed4851
Compare
| String requestId; | ||
|
|
||
| // Set up thread-local span that inherits state from HTTP headers | ||
| if (Strings.isNullOrEmpty(traceIdHeader)) { |
There was a problem hiding this comment.
I had to inline the trace creation to get both the span id and the trace id out, without creating a wrapper object. Maybe just reading the MDC here is simpler?
There was a problem hiding this comment.
Ya, I'd prefer the minimal change where we read the requestId from MDC here.
| @@ -136,6 +136,8 @@ final String getTraceId() { | |||
| return traceId; | |||
| } | |||
|
|
|||
| abstract Optional<String> getRequestId(); | |||
There was a problem hiding this comment.
We still store the request id so that it can be restored when a trace is set. However this getter is not exposed to clients of Tracers / Tracer
| @@ -146,7 +146,13 @@ public static void initTrace(Observability observability, String traceId) { | |||
| */ | |||
| @CheckReturnValue | |||
| public static OpenSpan startSpan(String operation, String parentSpanId, SpanType type) { | |||
| return getOrCreateCurrentTrace().startSpan(operation, parentSpanId, type); | |||
| Trace trace = getOrCreateCurrentTrace(); | |||
| boolean wasEmpty = trace.isEmpty(); | |||
There was a problem hiding this comment.
This is kinda sad - but definitely don't want to be setting the MDC property on every span open, so we have to know if it could have become active here. If traces had to be initialized with a span, this would be part of init/setTrace :(
| if (top.type() != SpanType.SERVER_INCOMING) { | ||
| return Optional.empty(); | ||
| } | ||
| return Optional.of(top.getSpanId()); |
There was a problem hiding this comment.
I think we have to pass around the value like originatingSpanId, when we create deferred traces we don't pass the full stack of spans (we don't want to allow other code to complete spans from our thread) but we still want to pass the same requestId.
There was a problem hiding this comment.
Hm, but we don't do that for originatingSpanId, do we? Not for sampled spans. So while I agree with this, I think it should be fixed for originatingSpanId and requestId together in a follow-up pr
|
Perhaps it's time to deprecate |
| boolean wasEmpty = trace.isEmpty(); | ||
| OpenSpan result = trace.startSpan(operation, type); | ||
| if (wasEmpty) { | ||
| setRequestIdIfPresent(trace.getRequestId()); |
There was a problem hiding this comment.
This feels like the wrong place to do this.
I think we should do what carter recommended (#364 (comment)) which then means that this only has to happen in one code path.
There was a problem hiding this comment.
I think we should instead
- initialize the requestId once via a new API (as Carter recommended), when creating a new trace initialized via a SERVER_INCOMING
- set the MDC when setting a trace as the current trace (i.e. in
Tracer.setTrace, just like we set the traceId MDC key) which has the advantage that whenever we apply a deferred trace on another thread (viaDeferredTracer.withTrace) it will set therequestIdat the right time too
@carterkozak thoughts? I had initial context on this but it seems like you/@ferozco have been review-requested by the load-balancing bots
|
Yep, that's exactly what I was thinking, thanks Dan. |
|
Proposal is up #574 |
|
Closing this out because #574 has been released. |
Logs from concurrent incoming requests with the same traceid are currently difficult
to tell apart (one can look at thread names etc, but not across executors).
After this PR
==COMMIT_MSG==
Introduce a new MDC property managed by Tracers, which stores a unique identifier
when the top span of the current trace is a SERVER_INCOMING span.
==COMMIT_MSG==
Possible downsides?