From 72a26f0b8e24d400a6e4f78eb70cc3d739ef1f13 Mon Sep 17 00:00:00 2001 From: James Baker Date: Tue, 30 Jul 2019 11:08:20 +0100 Subject: [PATCH 01/10] Request log tracing At the moment, we send trace ids and span ids with our requests. This is excellent, and provides some coarse grained information. That said, it's very limited - you can merely know that some number of requests were triggered by the same underlying operation. Here, when a trace is originated with a parent span, we keep track of that parent (called an 'originating' span id) and also send it with requests. This means that we can use request logs to piece together accurate service level tracing as well as trace logs. In other words, if I have a call graph which looks like: ```yml service a/foo: check auth: call auth service: auth service/check auth: do work: call work service: work service/do operation: call auth service: auth service/check auth: ``` then I will see that in the trace logs (sampled) but I can derive ```yml service a/foo: auth service/check auth: work service/do operation: auth service/check auth: ``` from the request logs on all requests. Currently this is possible when requests are single-threaded, but not when people call services in parallel. --- .../com/palantir/tracing/api/OpenSpan.java | 23 +++++++- .../tracing/api/TraceHttpHeaders.java | 12 ++++ .../okhttp3/OkhttpTraceInterceptor.java | 3 + .../okhttp3/OkhttpTraceInterceptorTest.java | 22 +++----- .../main/java/com/palantir/tracing/Trace.java | 56 +++++++++++++++++-- .../java/com/palantir/tracing/TraceTest.java | 35 ++++++++++++ 6 files changed, 132 insertions(+), 19 deletions(-) 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..02965131c 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,20 @@ 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); } 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..2787668a9 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 services, + * where a service's stack will typically contain a single parent span from a different service 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. For service-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..9e3504bc5 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,6 +73,7 @@ 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(); } @@ -101,6 +96,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(parentState.getSpanId()); } @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); + } } From 65f3cf4ba70780b21062c28349cc189bda6b05e9 Mon Sep 17 00:00:00 2001 From: James Baker Date: Tue, 30 Jul 2019 10:08:20 +0000 Subject: [PATCH 02/10] Add generated changelog entries --- changelog/@unreleased/pr-206.v2.yml | 6 ++++++ 1 file changed, 6 insertions(+) create mode 100644 changelog/@unreleased/pr-206.v2.yml 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 From d015b357c50d84f8ace66ebbe7426a440e23eeb3 Mon Sep 17 00:00:00 2001 From: James Baker Date: Tue, 30 Jul 2019 11:30:26 +0100 Subject: [PATCH 03/10] fix test --- .../palantir/tracing/okhttp3/OkhttpTraceInterceptorTest.java | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) 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 9e3504bc5..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 @@ -79,7 +79,8 @@ public void testPopulatesNewTrace_whenNoTraceIsPresentInGlobalState() throws IOE @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); @@ -96,7 +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(parentState.getSpanId()); + assertThat(intercepted.header(TraceHttpHeaders.ORIGINATING_SPAN_ID)).isEqualTo(originatingSpanId); } @Test From 68e1018a43a0a4025fc417c08082b095e2688368 Mon Sep 17 00:00:00 2001 From: James Baker Date: Tue, 30 Jul 2019 14:36:26 +0100 Subject: [PATCH 04/10] PR comments --- readme.md | 4 +++- .../com/palantir/tracing/api/OpenSpan.java | 20 +++++++++++++++++++ .../tracing/api/TraceHttpHeaders.java | 8 ++++---- 3 files changed, 27 insertions(+), 5 deletions(-) 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 02965131c..ac273e926 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 @@ -109,6 +109,26 @@ public static OpenSpan of( 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, + getNowInMicroSeconds(), + System.nanoTime(), + parentSpanId, + Optional.empty(), + spanId, + type); + } + private static long getNowInMicroSeconds() { Instant now = CLOCK.instant(); return (1000000 * now.getEpochSecond()) + (now.getNano() / 1000); 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 2787668a9..e518d9c4c 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 @@ -24,14 +24,14 @@ public interface TraceHttpHeaders { 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 services, - * where a service's stack will typically contain a single parent span from a different service at the bottom, + * 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. For service-internal tracing, the typical trace logs - * (with sampling) are still required. + * information to reconstruct a request-level trace, even when the trace is not sampled. + * For server-internal tracing, the typical trace loggs (with sampling) are still required. */ String ORIGINATING_SPAN_ID = "X-OrigSpanId"; } From 2d705c3f2f6d0a2c8a2e7c524b7be7df8b39aeca Mon Sep 17 00:00:00 2001 From: James Baker Date: Tue, 30 Jul 2019 15:35:17 +0100 Subject: [PATCH 05/10] fix accidental break --- .../src/main/java/com/palantir/tracing/api/OpenSpan.java | 9 +-------- 1 file changed, 1 insertion(+), 8 deletions(-) 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 ac273e926..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 @@ -119,14 +119,7 @@ public static OpenSpan of( String spanId, SpanType type, Optional parentSpanId) { - return of( - operation, - getNowInMicroSeconds(), - System.nanoTime(), - parentSpanId, - Optional.empty(), - spanId, - type); + return of(operation, spanId, type, parentSpanId, Optional.empty()); } private static long getNowInMicroSeconds() { From 51d90b5ba0c337bff35ba4141ae67a0b40ec604c Mon Sep 17 00:00:00 2001 From: James Baker Date: Tue, 30 Jul 2019 18:27:19 +0100 Subject: [PATCH 06/10] Update TraceHttpHeaders.java --- .../main/java/com/palantir/tracing/api/TraceHttpHeaders.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) 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 e518d9c4c..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 @@ -31,7 +31,7 @@ public interface TraceHttpHeaders { * 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 loggs (with sampling) are still required. + * For server-internal tracing, the typical trace logs (with sampling) are still required. */ String ORIGINATING_SPAN_ID = "X-OrigSpanId"; } From 9fe7ece30b2541d4dbaa8cc59050f29d0c097757 Mon Sep 17 00:00:00 2001 From: James Baker Date: Thu, 8 Aug 2019 14:16:12 +0100 Subject: [PATCH 07/10] Use parent span id instead of originating span in order to remain closer to zipkin spec --- readme.md | 4 +--- .../com/palantir/tracing/api/OpenSpan.java | 10 ++++++++-- .../palantir/tracing/api/TraceHttpHeaders.java | 12 ------------ .../okhttp3/OkhttpTraceInterceptor.java | 5 ++--- .../okhttp3/OkhttpTraceInterceptorTest.java | 18 ++++++++++++++++-- 5 files changed, 27 insertions(+), 22 deletions(-) diff --git a/readme.md b/readme.md index 2c8c52d2d..a42377ffe 100644 --- a/readme.md +++ b/readme.md @@ -15,9 +15,7 @@ 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. 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. +HTTP headers into all requests which get propagated by Jetty servers into subsequent client invocations. ## 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 2df3c41cb..b6287da1b 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 @@ -61,8 +61,14 @@ public abstract class OpenSpan { public abstract Optional getParentSpanId(); /** - * Returns the identifier of the 'originating' span if one exists. - * @see TraceHttpHeaders + * 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. + * + * If the trace is unsampled, 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. */ @Value.Parameter public abstract Optional getOriginatingSpanId(); 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 848292b8f..2aaba8991 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,16 +22,4 @@ 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 3634f888c..055862c58 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 @@ -50,9 +50,8 @@ public Response intercept(Chain chain) throws IOException { .addHeader(TraceHttpHeaders.IS_SAMPLED, Tracer.isTraceObservable() ? "1" : "0"); 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()); + } else if (span.getOriginatingSpanId().isPresent()) { + tracedRequest.header(TraceHttpHeaders.PARENT_SPAN_ID, span.getOriginatingSpanId().get()); } Response response; 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 edeb811b6..052a8aea9 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 @@ -73,7 +73,6 @@ 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(); } @@ -97,7 +96,6 @@ 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 @@ -120,6 +118,22 @@ public void testHeaders_whenTraceIsNotObservable() throws IOException { assertThat(intercepted.header(TraceHttpHeaders.IS_SAMPLED)).isEqualTo("0"); } + @Test + public void testHeaders_notSampledwhenOriginatingSpanPresent() throws IOException { + Tracer.initTrace(Observability.DO_NOT_SAMPLE, Tracers.randomId()); + String originatingSpan = "originating"; + Tracer.startSpan("operation", originatingSpan, SpanType.SERVER_INCOMING); + String traceId = Tracer.getTraceId(); + OkhttpTraceInterceptor.INSTANCE.intercept(chain); + verify(chain).proceed(requestCaptor.capture()); + Request intercepted = requestCaptor.getValue(); + assertThat(intercepted.header(TraceHttpHeaders.SPAN_ID)).isNotNull(); + assertThat(intercepted.header(TraceHttpHeaders.PARENT_SPAN_ID)).isEqualTo(originatingSpan); + assertThat(intercepted.header(TraceHttpHeaders.TRACE_ID)).isEqualTo(traceId); + assertThat(intercepted.header(TraceHttpHeaders.IS_SAMPLED)).isEqualTo("0"); + + } + @Test public void testPopsSpan() throws IOException { OpenSpan before = Tracer.startSpan(""); From 80407622f4e031bcadf342584aa3991cf711215f Mon Sep 17 00:00:00 2001 From: James Baker Date: Thu, 8 Aug 2019 14:21:24 +0100 Subject: [PATCH 08/10] Fast --- .../palantir/tracing/okhttp3/OkhttpTraceInterceptorTest.java | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) 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 052a8aea9..e4ae7778d 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 @@ -119,10 +119,10 @@ public void testHeaders_whenTraceIsNotObservable() throws IOException { } @Test - public void testHeaders_notSampledwhenOriginatingSpanPresent() throws IOException { + public void testHeaders_notSampledWhenOriginatingSpanPresent() throws IOException { Tracer.initTrace(Observability.DO_NOT_SAMPLE, Tracers.randomId()); String originatingSpan = "originating"; - Tracer.startSpan("operation", originatingSpan, SpanType.SERVER_INCOMING); + Tracer.fastStartSpan("operation", originatingSpan, SpanType.SERVER_INCOMING); String traceId = Tracer.getTraceId(); OkhttpTraceInterceptor.INSTANCE.intercept(chain); verify(chain).proceed(requestCaptor.capture()); From f4557ef190ee9ea8473d8dd3cc51b40037f030e4 Mon Sep 17 00:00:00 2001 From: James Baker Date: Thu, 8 Aug 2019 14:27:08 +0100 Subject: [PATCH 09/10] Revert "Fast" This reverts commit 80407622f4e031bcadf342584aa3991cf711215f. --- .../palantir/tracing/okhttp3/OkhttpTraceInterceptorTest.java | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) 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 e4ae7778d..052a8aea9 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 @@ -119,10 +119,10 @@ public void testHeaders_whenTraceIsNotObservable() throws IOException { } @Test - public void testHeaders_notSampledWhenOriginatingSpanPresent() throws IOException { + public void testHeaders_notSampledwhenOriginatingSpanPresent() throws IOException { Tracer.initTrace(Observability.DO_NOT_SAMPLE, Tracers.randomId()); String originatingSpan = "originating"; - Tracer.fastStartSpan("operation", originatingSpan, SpanType.SERVER_INCOMING); + Tracer.startSpan("operation", originatingSpan, SpanType.SERVER_INCOMING); String traceId = Tracer.getTraceId(); OkhttpTraceInterceptor.INSTANCE.intercept(chain); verify(chain).proceed(requestCaptor.capture()); From f459a3c41c0442fb3115baa103c35766a2e4ec71 Mon Sep 17 00:00:00 2001 From: James Baker Date: Thu, 8 Aug 2019 14:27:12 +0100 Subject: [PATCH 10/10] Revert "Use parent span id instead of originating span in order to remain closer" This reverts commit 9fe7ece30b2541d4dbaa8cc59050f29d0c097757. --- readme.md | 4 +++- .../com/palantir/tracing/api/OpenSpan.java | 10 ++-------- .../palantir/tracing/api/TraceHttpHeaders.java | 12 ++++++++++++ .../okhttp3/OkhttpTraceInterceptor.java | 5 +++-- .../okhttp3/OkhttpTraceInterceptorTest.java | 18 ++---------------- 5 files changed, 22 insertions(+), 27 deletions(-) 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 b6287da1b..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 @@ -61,14 +61,8 @@ public abstract class OpenSpan { public abstract Optional getParentSpanId(); /** - * 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. - * - * If the trace is unsampled, 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. + * Returns the identifier of the 'originating' span if one exists. + * @see TraceHttpHeaders */ @Value.Parameter public abstract Optional getOriginatingSpanId(); 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 055862c58..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 @@ -50,8 +50,9 @@ public Response intercept(Chain chain) throws IOException { .addHeader(TraceHttpHeaders.IS_SAMPLED, Tracer.isTraceObservable() ? "1" : "0"); if (span.getParentSpanId().isPresent()) { tracedRequest.header(TraceHttpHeaders.PARENT_SPAN_ID, span.getParentSpanId().get()); - } else if (span.getOriginatingSpanId().isPresent()) { - tracedRequest.header(TraceHttpHeaders.PARENT_SPAN_ID, span.getOriginatingSpanId().get()); + } + if (span.getOriginatingSpanId().isPresent()) { + tracedRequest.header(TraceHttpHeaders.ORIGINATING_SPAN_ID, span.getOriginatingSpanId().get()); } Response response; 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 052a8aea9..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 @@ -73,6 +73,7 @@ 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(); } @@ -96,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 @@ -118,22 +120,6 @@ public void testHeaders_whenTraceIsNotObservable() throws IOException { assertThat(intercepted.header(TraceHttpHeaders.IS_SAMPLED)).isEqualTo("0"); } - @Test - public void testHeaders_notSampledwhenOriginatingSpanPresent() throws IOException { - Tracer.initTrace(Observability.DO_NOT_SAMPLE, Tracers.randomId()); - String originatingSpan = "originating"; - Tracer.startSpan("operation", originatingSpan, SpanType.SERVER_INCOMING); - String traceId = Tracer.getTraceId(); - OkhttpTraceInterceptor.INSTANCE.intercept(chain); - verify(chain).proceed(requestCaptor.capture()); - Request intercepted = requestCaptor.getValue(); - assertThat(intercepted.header(TraceHttpHeaders.SPAN_ID)).isNotNull(); - assertThat(intercepted.header(TraceHttpHeaders.PARENT_SPAN_ID)).isEqualTo(originatingSpan); - assertThat(intercepted.header(TraceHttpHeaders.TRACE_ID)).isEqualTo(traceId); - assertThat(intercepted.header(TraceHttpHeaders.IS_SAMPLED)).isEqualTo("0"); - - } - @Test public void testPopsSpan() throws IOException { OpenSpan before = Tracer.startSpan("");