Request log tracing

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

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: <Trace ID>`
-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: <Originating Span ID>`
+header which enables request logs to be considered a useful subset of the trace events, even on unsampled requests.
 
 ## Usage
 

tracing-api/src/main/java/com/palantir/tracing/api/OpenSpan.java

@@ -60,6 +60,13 @@ public abstract class OpenSpan {
     @Value.Parameter
     public abstract Optional<String> getParentSpanId();
 
+    /**
+     * Returns the identifier of the 'originating' span if one exists.
+     * @see TraceHttpHeaders
+     */
+    @Value.Parameter
+    public abstract Optional<String> 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<String> parentSpanId) {
-        return ImmutableOpenSpan.of(operation, getNowInMicroSeconds(), System.nanoTime(), parentSpanId, spanId, type);
+    public static OpenSpan of(
+            String operation,
+            String spanId,
+            SpanType type,
+            Optional<String> parentSpanId,
+            Optional<String> 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<String> parentSpanId) {
+        return of(operation, spanId, type, parentSpanId, Optional.empty());
     }
 
     private static long getNowInMicroSeconds() {

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";
 }

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 {

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<Request> requestCaptor;
-
-    @Captor
-    private ArgumentCaptor<Span> spanCaptor;
+    @Mock private Interceptor.Chain chain;
+    @Mock private SpanObserver observer;
+    @Captor private ArgumentCaptor<Request> requestCaptor;
+    @Captor private ArgumentCaptor<Span> 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

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 <T> Optional<T> orElse(Optional<T> left, Optional<T> 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<String> 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<String> 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<String> 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<String> parentSpanId) {
+            if (numberOfSpans == 0) {
+                originatingSpanId = parentSpanId;
+            }
             numberOfSpans++;
         }
 
@@ -225,6 +265,9 @@ Optional<OpenSpan> pop() {
             if (numberOfSpans > 0) {
                 numberOfSpans--;
             }
+            if (numberOfSpans == 0) {
+                originatingSpanId = Optional.empty();
+            }
             return Optional.empty();
         }
 
@@ -239,6 +282,11 @@ boolean isObservable() {
             return false;
         }
 
+        @Override
+        Optional<String> getOriginatingSpanId() {
+            return originatingSpanId;
+        }
+
         @Override
         Trace deepCopy() {
             return new Unsampled(numberOfSpans, getTraceId());

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);
+    }
 }