diff --git a/changelog/@unreleased/pr-206.v2.yml b/changelog/@unreleased/pr-206.v2.yml new file mode 100644 index 000000000..b51ba7efc --- /dev/null +++ b/changelog/@unreleased/pr-206.v2.yml @@ -0,0 +1,6 @@ +type: improvement +improvement: + description: Add originating span id to requests in order to enable request log + tracing + links: + - https://github.com/palantir/tracing-java/pull/206 diff --git a/readme.md b/readme.md index a42377ffe..2c8c52d2d 100644 --- a/readme.md +++ b/readme.md @@ -15,7 +15,9 @@ Clients and servers propagate call trace ids across JVM boundaries according to the [Zipkin](https://github.com/openzipkin/zipkin) specification. In particular, clients insert `X-B3-TraceId: ` -HTTP headers into all requests which get propagated by Jetty servers into subsequent client invocations. +HTTP headers into all requests which get propagated by Jetty servers into subsequent client invocations. We enhance +the Zipkin spec in one regard; with outgoing traces we additionally send an `X-OrigSpanId: ` +header which enables request logs to be considered a useful subset of the trace events, even on unsampled requests. ## Usage diff --git a/tracing-api/src/main/java/com/palantir/tracing/api/OpenSpan.java b/tracing-api/src/main/java/com/palantir/tracing/api/OpenSpan.java index f16a7fcee..2df3c41cb 100644 --- a/tracing-api/src/main/java/com/palantir/tracing/api/OpenSpan.java +++ b/tracing-api/src/main/java/com/palantir/tracing/api/OpenSpan.java @@ -60,6 +60,13 @@ public abstract class OpenSpan { @Value.Parameter public abstract Optional getParentSpanId(); + /** + * Returns the identifier of the 'originating' span if one exists. + * @see TraceHttpHeaders + */ + @Value.Parameter + public abstract Optional getOriginatingSpanId(); + /** * Returns a globally unique identifier representing a single span within the call trace. */ @@ -86,8 +93,33 @@ public static Builder builder() { /** * Use this factory method to avoid allocate {@link Builder} in hot path. */ - public static OpenSpan of(String operation, String spanId, SpanType type, Optional parentSpanId) { - return ImmutableOpenSpan.of(operation, getNowInMicroSeconds(), System.nanoTime(), parentSpanId, spanId, type); + public static OpenSpan of( + String operation, + String spanId, + SpanType type, + Optional parentSpanId, + Optional originatingSpanId) { + return ImmutableOpenSpan.of( + operation, + getNowInMicroSeconds(), + System.nanoTime(), + parentSpanId, + originatingSpanId, + spanId, + type); + } + + /** + * Deprecated. + * @deprecated Use the variant that accepts an originating span id + */ + @Deprecated + public static OpenSpan of( + String operation, + String spanId, + SpanType type, + Optional parentSpanId) { + return of(operation, spanId, type, parentSpanId, Optional.empty()); } private static long getNowInMicroSeconds() { diff --git a/tracing-api/src/main/java/com/palantir/tracing/api/TraceHttpHeaders.java b/tracing-api/src/main/java/com/palantir/tracing/api/TraceHttpHeaders.java index 2aaba8991..848292b8f 100644 --- a/tracing-api/src/main/java/com/palantir/tracing/api/TraceHttpHeaders.java +++ b/tracing-api/src/main/java/com/palantir/tracing/api/TraceHttpHeaders.java @@ -22,4 +22,16 @@ public interface TraceHttpHeaders { String PARENT_SPAN_ID = "X-B3-ParentSpanId"; String SPAN_ID = "X-B3-SpanId"; String IS_SAMPLED = "X-B3-Sampled"; // Boolean (either “1” or “0”, can be absent) + + /** + * Conceptually, a trace is a stack of spans. In implementation, this is actually many stacks, in many servers, + * where a server's stack will typically contain a single parent span from a different server at the bottom, + * and many spans of its own above it. + * + * By communicating this deepest span id with future network calls as an 'originating' span id, this enables + * network-level tracing to be enabled always in a low-fidelity form, with request logs containing enough + * information to reconstruct a request-level trace, even when the trace is not sampled. + * For server-internal tracing, the typical trace logs (with sampling) are still required. + */ + String ORIGINATING_SPAN_ID = "X-OrigSpanId"; } diff --git a/tracing-okhttp3/src/main/java/com/palantir/tracing/okhttp3/OkhttpTraceInterceptor.java b/tracing-okhttp3/src/main/java/com/palantir/tracing/okhttp3/OkhttpTraceInterceptor.java index f37e591dd..3634f888c 100644 --- a/tracing-okhttp3/src/main/java/com/palantir/tracing/okhttp3/OkhttpTraceInterceptor.java +++ b/tracing-okhttp3/src/main/java/com/palantir/tracing/okhttp3/OkhttpTraceInterceptor.java @@ -51,6 +51,9 @@ public Response intercept(Chain chain) throws IOException { if (span.getParentSpanId().isPresent()) { tracedRequest.header(TraceHttpHeaders.PARENT_SPAN_ID, span.getParentSpanId().get()); } + if (span.getOriginatingSpanId().isPresent()) { + tracedRequest.header(TraceHttpHeaders.ORIGINATING_SPAN_ID, span.getOriginatingSpanId().get()); + } Response response; try { diff --git a/tracing-okhttp3/src/test/java/com/palantir/tracing/okhttp3/OkhttpTraceInterceptorTest.java b/tracing-okhttp3/src/test/java/com/palantir/tracing/okhttp3/OkhttpTraceInterceptorTest.java index efd39d097..edeb811b6 100644 --- a/tracing-okhttp3/src/test/java/com/palantir/tracing/okhttp3/OkhttpTraceInterceptorTest.java +++ b/tracing-okhttp3/src/test/java/com/palantir/tracing/okhttp3/OkhttpTraceInterceptorTest.java @@ -36,28 +36,22 @@ import org.junit.After; import org.junit.Before; import org.junit.Test; +import org.junit.runner.RunWith; import org.mockito.ArgumentCaptor; import org.mockito.Captor; import org.mockito.Mock; -import org.mockito.MockitoAnnotations; +import org.mockito.junit.MockitoJUnitRunner; +@RunWith(MockitoJUnitRunner.class) public final class OkhttpTraceInterceptorTest { - @Mock - private Interceptor.Chain chain; - - @Mock - private SpanObserver observer; - - @Captor - private ArgumentCaptor requestCaptor; - - @Captor - private ArgumentCaptor spanCaptor; + @Mock private Interceptor.Chain chain; + @Mock private SpanObserver observer; + @Captor private ArgumentCaptor requestCaptor; + @Captor private ArgumentCaptor spanCaptor; @Before public void before() { - MockitoAnnotations.initMocks(this); Request request = new Request.Builder().url("http://localhost").build(); when(chain.request()).thenReturn(request); Tracer.subscribe("", observer); @@ -79,12 +73,14 @@ public void testPopulatesNewTrace_whenNoTraceIsPresentInGlobalState() throws IOE Request intercepted = requestCaptor.getValue(); assertThat(intercepted.header(TraceHttpHeaders.SPAN_ID)).isNotNull(); assertThat(intercepted.header(TraceHttpHeaders.TRACE_ID)).isNotNull(); + assertThat(intercepted.header(TraceHttpHeaders.ORIGINATING_SPAN_ID)).isNull(); assertThat(intercepted.header(TraceHttpHeaders.PARENT_SPAN_ID)).isNull(); } @Test public void testPopulatesNewTrace_whenParentTraceIsPresent() throws IOException { - OpenSpan parentState = Tracer.startSpan("operation"); + String originatingSpanId = "originating Span"; + OpenSpan parentState = Tracer.startSpan("operation", originatingSpanId, SpanType.SERVER_INCOMING); String traceId = Tracer.getTraceId(); try { OkhttpTraceInterceptor.INSTANCE.intercept(chain); @@ -101,6 +97,7 @@ public void testPopulatesNewTrace_whenParentTraceIsPresent() throws IOException assertThat(intercepted.header(TraceHttpHeaders.SPAN_ID)).isNotEqualTo(parentState.getSpanId()); assertThat(intercepted.header(TraceHttpHeaders.TRACE_ID)).isEqualTo(traceId); assertThat(intercepted.header(TraceHttpHeaders.PARENT_SPAN_ID)).isEqualTo(parentState.getSpanId()); + assertThat(intercepted.header(TraceHttpHeaders.ORIGINATING_SPAN_ID)).isEqualTo(originatingSpanId); } @Test diff --git a/tracing/src/main/java/com/palantir/tracing/Trace.java b/tracing/src/main/java/com/palantir/tracing/Trace.java index c22d9d48a..ae32a7aba 100644 --- a/tracing/src/main/java/com/palantir/tracing/Trace.java +++ b/tracing/src/main/java/com/palantir/tracing/Trace.java @@ -59,7 +59,12 @@ private Trace(String traceId) { final OpenSpan startSpan(String operation, String parentSpanId, SpanType type) { checkState(isEmpty(), "Cannot start a span with explicit parent if the current thread's trace is non-empty"); checkArgument(!Strings.isNullOrEmpty(parentSpanId), "parentSpanId must be non-empty"); - OpenSpan span = OpenSpan.of(operation, Tracers.randomId(), type, Optional.of(parentSpanId)); + OpenSpan span = OpenSpan.of( + operation, + Tracers.randomId(), + type, + Optional.of(parentSpanId), + orElse(getOriginatingSpanId(), Optional.of(parentSpanId))); push(span); return span; } @@ -74,15 +79,32 @@ final OpenSpan startSpan(String operation, SpanType type) { final OpenSpan span; // Avoid lambda allocation in hot paths if (prevState.isPresent()) { - span = OpenSpan.of(operation, Tracers.randomId(), type, Optional.of(prevState.get().getSpanId())); + span = OpenSpan.of( + operation, + Tracers.randomId(), + type, + Optional.of(prevState.get().getSpanId()), + orElse(getOriginatingSpanId(), prevState.get().getParentSpanId())); } else { - span = OpenSpan.of(operation, Tracers.randomId(), type, Optional.empty()); + span = OpenSpan.of( + operation, + Tracers.randomId(), + type, + Optional.empty(), + getOriginatingSpanId()); } push(span); return span; } + private static Optional orElse(Optional left, Optional right) { + if (left.isPresent()) { + return left; + } + return right; + } + /** * Like {@link #startSpan(String, String, SpanType)}, but does not return an {@link OpenSpan}. */ @@ -114,6 +136,8 @@ final String getTraceId() { return traceId; } + abstract Optional getOriginatingSpanId(); + /** Returns a copy of this Trace which can be independently mutated. */ abstract Trace deepCopy(); @@ -171,6 +195,14 @@ boolean isObservable() { return true; } + @Override + Optional getOriginatingSpanId() { + if (stack.isEmpty()) { + return Optional.empty(); + } + return stack.peekLast().getParentSpanId(); + } + @Override Trace deepCopy() { return new Sampled(new ArrayDeque<>(stack), getTraceId()); @@ -188,6 +220,7 @@ private static final class Unsampled extends Trace { * This allows thread trace state to be cleared when all "started" spans have been "removed". */ private int numberOfSpans; + private Optional originatingSpanId = Optional.empty(); private Unsampled(int numberOfSpans, String traceId) { super(traceId); @@ -201,7 +234,7 @@ private Unsampled(String traceId) { @Override void fastStartSpan(String operation, String parentSpanId, SpanType type) { - fastStartSpan(operation, type); + startSpan(Optional.of(parentSpanId)); } @Override @@ -211,6 +244,13 @@ void fastStartSpan(String operation, SpanType type) { @Override protected void push(OpenSpan span) { + startSpan(span.getParentSpanId()); + } + + private void startSpan(Optional parentSpanId) { + if (numberOfSpans == 0) { + originatingSpanId = parentSpanId; + } numberOfSpans++; } @@ -225,6 +265,9 @@ Optional pop() { if (numberOfSpans > 0) { numberOfSpans--; } + if (numberOfSpans == 0) { + originatingSpanId = Optional.empty(); + } return Optional.empty(); } @@ -239,6 +282,11 @@ boolean isObservable() { return false; } + @Override + Optional getOriginatingSpanId() { + return originatingSpanId; + } + @Override Trace deepCopy() { return new Unsampled(numberOfSpans, getTraceId()); diff --git a/tracing/src/test/java/com/palantir/tracing/TraceTest.java b/tracing/src/test/java/com/palantir/tracing/TraceTest.java index 0c1158ddc..a6041aadc 100644 --- a/tracing/src/test/java/com/palantir/tracing/TraceTest.java +++ b/tracing/src/test/java/com/palantir/tracing/TraceTest.java @@ -24,6 +24,7 @@ import org.junit.Test; public final class TraceTest { + private static final String ORIGINATING_SPAN_ID = "originating span id"; @Test public void constructTrace_emptyTraceId() { @@ -40,4 +41,38 @@ public void testToString() { .contains(span.getOperation()) .contains(span.getSpanId()); } + + @Test + public void testOriginatingTraceId_slow_sampled() { + Trace trace = Trace.of(true, "traceId"); + OpenSpan originating = trace.startSpan("1", ORIGINATING_SPAN_ID, SpanType.LOCAL); + assertThat(originating.getOriginatingSpanId()).contains(ORIGINATING_SPAN_ID); + OpenSpan span = trace.startSpan("2", SpanType.LOCAL); + assertThat(span.getOriginatingSpanId()).contains(ORIGINATING_SPAN_ID); + } + + @Test + public void testOriginatingTraceId_fast_sampled() { + Trace trace = Trace.of(true, "traceId"); + trace.fastStartSpan("1", ORIGINATING_SPAN_ID, SpanType.LOCAL); + OpenSpan span = trace.startSpan("2", SpanType.LOCAL); + assertThat(span.getOriginatingSpanId()).contains(ORIGINATING_SPAN_ID); + } + + @Test + public void testOriginatingTraceId_slow_unsampled() { + Trace trace = Trace.of(false, "traceId"); + OpenSpan originating = trace.startSpan("1", ORIGINATING_SPAN_ID, SpanType.LOCAL); + assertThat(originating.getOriginatingSpanId()).contains(ORIGINATING_SPAN_ID); + OpenSpan span = trace.startSpan("2", SpanType.LOCAL); + assertThat(span.getOriginatingSpanId()).contains(ORIGINATING_SPAN_ID); + } + + @Test + public void testOriginatingTraceId_fast_unsampled() { + Trace trace = Trace.of(false, "traceId"); + trace.fastStartSpan("1", ORIGINATING_SPAN_ID, SpanType.LOCAL); + OpenSpan span = trace.startSpan("2", SpanType.LOCAL); + assertThat(span.getOriginatingSpanId()).contains(ORIGINATING_SPAN_ID); + } }