Ensures Span.timestamp/duration are not reported on remote spans (#443)

This ensures spans that have remote set to true don't send
Span.timestamp/duration.

In the RPC span model, the client owns the timestamp and duration of the
span. If we were propagated an id, we can assume that we shouldn't
report timestamp or duration, rather let the client do that. Worst case
we were propagated an unreported ID and Zipkin backfills timestamp and
duration.

Author: adriancole

spring-cloud-sleuth-samples/spring-cloud-sleuth-sample-messaging/src/test/java/integration/MessagingApplicationTests.java

@@ -114,7 +114,7 @@ private void thenTheSpansHaveProperParentStructure() {
 		Optional<Span> eventReceivedSpan = findSpanWithAnnotation(Constants.CLIENT_RECV);
 		Optional<Span> lastHttpSpansParent = findLastHttpSpansParent();
 		// "http:/parent/" -> "home" -> "message:messages" -> "http:/foo" (CS + CR) -> "http:/foo" (SS) -> "foo"
-		Collections.sort(this.integrationTestSpanCollector.hashedSpans, (s1, s2) -> s1.timestamp.compareTo(s2.timestamp));
+		Collections.sort(this.integrationTestSpanCollector.hashedSpans);
 		thenAllSpansArePresent(firstHttpSpan, eventSpans, lastHttpSpansParent, eventSentSpan, eventReceivedSpan);
 		then(this.integrationTestSpanCollector.hashedSpans).as("There were 6 spans").hasSize(6);
 		log.info("Checking the parent child structure");

spring-cloud-sleuth-zipkin-stream/src/main/java/org/springframework/cloud/sleuth/zipkin/stream/ConvertToZipkinSpanList.java

@@ -89,9 +89,15 @@ static zipkin.Span convert(Span span, Host host) {
 		if (hasClientSend(span)) {
 			ensureServerAddr(span, zipkinSpan, ep);
 		}
-		zipkinSpan.timestamp(span.getBegin() * 1000);
-		if (!span.isRunning()) { // duration is authoritative, only write when the span stopped
-			zipkinSpan.duration(calculateDurationInMicros(span));
+		// In the RPC span model, the client owns the timestamp and duration of the span. If we
+		// were propagated an id, we can assume that we shouldn't report timestamp or duration,
+		// rather let the client do that. Worst case we were propagated an unreported ID and
+		// Zipkin backfills timestamp and duration.
+		if (!span.isRemote()) {
+			zipkinSpan.timestamp(span.getBegin() * 1000);
+			if (!span.isRunning()) { // duration is authoritative, only write when the span stopped
+				zipkinSpan.duration(calculateDurationInMicros(span));
+			}
 		}
 		zipkinSpan.traceId(span.getTraceId());
 		if (span.getParents().size() > 0) {
@@ -174,4 +180,4 @@ private static org.springframework.cloud.sleuth.Log hasLog(String logName, Span
 		}
 		return null;
 	}
-}
+}

spring-cloud-sleuth-zipkin-stream/src/test/java/org/springframework/cloud/sleuth/zipkin/stream/ConvertToZipkinSpanListTests.java

@@ -155,7 +155,7 @@ public void setsTheDurationToTheDifferenceBetweenCRandCS()
 	/** Zipkin's duration should only be set when the span is finished. */
 	@Test
 	public void doesntSetDurationWhenStillRunning() {
-		Span running = Span.builder().traceId(1L).name("http:parent").remote(true).build();
+		Span running = Span.builder().traceId(1L).name("http:child").build();
 		Spans spans = new Spans(this.host, Collections.singletonList(running));
 		zipkin.Span result = ConvertToZipkinSpanList.convert(spans).get(0);
 
@@ -165,9 +165,31 @@ public void doesntSetDurationWhenStillRunning() {
 				.isNull();
 	}
 
+	/**
+	 * In the RPC span model, the client owns the timestamp and duration of the span. If we
+	 * were propagated an id, we can assume that we shouldn't report timestamp or duration,
+	 * rather let the client do that. Worst case we were propagated an unreported ID and
+	 * Zipkin backfills timestamp and duration.
+	 */
+	@Test
+	public void doesntSetTimestampOrDurationWhenRemote() {
+		Span span = span("foo", true);
+		Spans spans = new Spans(this.host, Collections.singletonList(span));
+		zipkin.Span result = ConvertToZipkinSpanList.convert(spans).get(0);
+
+		assertThat(result.timestamp)
+				.isNull();
+		assertThat(result.duration)
+				.isNull();
+	}
+
 	Span span(String name) {
+		return span(name, false);
+	}
+
+	Span span(String name, boolean remote) {
 		Long id = new Random().nextLong();
-		return new Span(1, 3, "message:" + name, id, Collections.<Long>emptyList(), id, true, true,
+		return new Span(1, 3, "message:" + name, id, Collections.<Long>emptyList(), id, remote, true,
 				"process");
 	}
-}
+}

spring-cloud-sleuth-zipkin-stream/src/test/java/org/springframework/cloud/sleuth/zipkin/stream/ZipkinMessageListenerTests.java

@@ -34,18 +34,37 @@ public class ZipkinMessageListenerTests {
 			.ipv4(1 << 24 | 2 << 16 | 3 << 8 | 4)
 			.port(8080).build();
 
+	/**
+	 * In the RPC span model, the client owns the timestamp and duration of the span. If we
+	 * were propagated an id, we can assume that we shouldn't report timestamp or duration,
+	 * rather let the client do that. Worst case we were propagated an unreported ID and
+	 * Zipkin backfills timestamp and duration.
+	 */
+	@Test
+	public void doesntSetTimestampOrDurationWhenRemote() {
+		this.span.stop();
+		zipkin.Span result = ConvertToZipkinSpanList.convert(this.span, this.host);
+
+		assertThat(result.timestamp)
+				.isNull();
+		assertThat(result.duration)
+				.isNull();
+	}
+
 	/** Sleuth timestamps are millisecond granularity while zipkin is microsecond. */
 	@Test
 	public void convertsTimestampAndDurationToMicroseconds() {
+		Span span = new Span(1, 3, "http:name", 1L, Collections.<Long>emptyList(), 2L, false, true,
+				"process");
 		long start = System.currentTimeMillis();
-		this.span.logEvent("hystrix/retry"); // System.currentTimeMillis
+		span.logEvent("hystrix/retry"); // System.currentTimeMillis
 
-		zipkin.Span result = ConvertToZipkinSpanList.convert(this.span, this.host);
+		zipkin.Span result = ConvertToZipkinSpanList.convert(span, this.host);
 
 		assertThat(result.timestamp)
-				.isEqualTo(this.span.getBegin() * 1000);
+				.isEqualTo(span.getBegin() * 1000);
 		assertThat(result.duration)
-				.isEqualTo((this.span.getEnd() - this.span.getBegin()) * 1000);
+				.isEqualTo((span.getEnd() - span.getBegin()) * 1000);
 		assertThat(result.annotations.get(0).timestamp)
 				.isGreaterThanOrEqualTo(start * 1000)
 				.isLessThanOrEqualTo(System.currentTimeMillis() * 1000);

spring-cloud-sleuth-zipkin/src/main/java/org/springframework/cloud/sleuth/zipkin/ZipkinSpanListener.java

@@ -85,9 +85,15 @@ zipkin.Span convert(Span span) {
 		if (hasClientSend(span)) {
 			ensureServerAddr(span, zipkinSpan);
 		}
-		zipkinSpan.timestamp(span.getBegin() * 1000L);
-		if (!span.isRunning()) { // duration is authoritative, only write when the span stopped
-			zipkinSpan.duration(calculateDurationInMicros(span));
+		// In the RPC span model, the client owns the timestamp and duration of the span. If we
+		// were propagated an id, we can assume that we shouldn't report timestamp or duration,
+		// rather let the client do that. Worst case we were propagated an unreported ID and
+		// Zipkin backfills timestamp and duration.
+		if (!span.isRemote()) {
+			zipkinSpan.timestamp(span.getBegin() * 1000L);
+			if (!span.isRunning()) { // duration is authoritative, only write when the span stopped
+				zipkinSpan.duration(calculateDurationInMicros(span));
+			}
 		}
 		zipkinSpan.traceId(span.getTraceId());
 		if (span.getParents().size() > 0) {

spring-cloud-sleuth-zipkin/src/test/java/org/springframework/cloud/sleuth/zipkin/ZipkinSpanListenerTests.java

@@ -17,6 +17,7 @@
 package org.springframework.cloud.sleuth.zipkin;
 
 import java.util.ArrayList;
+import java.util.Collections;
 import java.util.List;
 import javax.annotation.PostConstruct;
 
@@ -64,16 +65,17 @@ public void init() {
 	/** Sleuth timestamps are millisecond granularity while zipkin is microsecond. */
 	@Test
 	public void convertsTimestampToMicrosecondsAndSetsDurationToAccumulatedMicros() {
+		Span span = Span.builder().traceId(1L).name("http:api").build();
 		long start = System.currentTimeMillis();
-		this.parent.logEvent("hystrix/retry"); // System.currentTimeMillis
-		this.parent.stop();
+		span.logEvent("hystrix/retry"); // System.currentTimeMillis
+		span.stop();
 
-		zipkin.Span result = this.spanReporter.convert(this.parent);
+		zipkin.Span result = this.spanReporter.convert(span);
 
 		assertThat(result.timestamp)
-				.isEqualTo(this.parent.getBegin() * 1000);
+				.isEqualTo(span.getBegin() * 1000);
 		assertThat(result.duration)
-				.isEqualTo(this.parent.getAccumulatedMicros());
+				.isEqualTo(span.getAccumulatedMicros());
 		assertThat(result.annotations.get(0).timestamp)
 				.isGreaterThanOrEqualTo(start * 1000)
 				.isLessThanOrEqualTo(System.currentTimeMillis() * 1000);
@@ -82,36 +84,55 @@ public void convertsTimestampToMicrosecondsAndSetsDurationToAccumulatedMicros()
 	@Test
 	public void setsTheDurationToTheDifferenceBetweenCRandCS()
 			throws InterruptedException {
-		this.parent.logEvent(Span.CLIENT_SEND);
+		Span span = Span.builder().traceId(1L).name("http:api").build();
+		span.logEvent(Span.CLIENT_SEND);
 		Thread.sleep(10);
-		this.parent.logEvent(Span.CLIENT_RECV);
+		span.logEvent(Span.CLIENT_RECV);
 		Thread.sleep(20);
-		this.parent.stop();
+		span.stop();
 
-		zipkin.Span result = this.spanReporter.convert(this.parent);
+		zipkin.Span result = this.spanReporter.convert(span);
 
 		assertThat(result.timestamp)
-				.isEqualTo(this.parent.getBegin() * 1000);
-		long clientSendTimestamp = this.parent.logs().stream().filter(log -> Span.CLIENT_SEND.equals(log.getEvent()))
+				.isEqualTo(span.getBegin() * 1000);
+		long clientSendTimestamp = span.logs().stream().filter(log -> Span.CLIENT_SEND.equals(log.getEvent()))
 				.findFirst().get().getTimestamp();
-		long clientRecvTimestamp = this.parent.logs().stream().filter(log -> Span.CLIENT_RECV.equals(log.getEvent()))
+		long clientRecvTimestamp = span.logs().stream().filter(log -> Span.CLIENT_RECV.equals(log.getEvent()))
 				.findFirst().get().getTimestamp();
 		assertThat(result.duration)
-				.isNotEqualTo(this.parent.getAccumulatedMicros())
+				.isNotEqualTo(span.getAccumulatedMicros())
 				.isEqualTo((clientRecvTimestamp - clientSendTimestamp) * 1000);
 	}
 
 	/** Zipkin's duration should only be set when the span is finished. */
 	@Test
 	public void doesntSetDurationWhenStillRunning() {
-		zipkin.Span result = this.spanReporter.convert(this.parent);
+		Span span = Span.builder().traceId(1L).name("http:api").build();
+		zipkin.Span result = this.spanReporter.convert(span);
 
 		assertThat(result.timestamp)
 				.isGreaterThan(0); // sanity check it did start
 		assertThat(result.duration)
 				.isNull();
 	}
 
+	/**
+	 * In the RPC span model, the client owns the timestamp and duration of the span. If we
+	 * were propagated an id, we can assume that we shouldn't report timestamp or duration,
+	 * rather let the client do that. Worst case we were propagated an unreported ID and
+	 * Zipkin backfills timestamp and duration.
+	 */
+	@Test
+	public void doesntSetTimestampOrDurationWhenRemote() {
+		this.parent.stop();
+		zipkin.Span result = this.spanReporter.convert(this.parent);
+
+		assertThat(result.timestamp)
+				.isNull();
+		assertThat(result.duration)
+				.isNull();
+	}
+
 	/** Sleuth host corresponds to annotation/binaryAnnotation.host in zipkin. */
 	@Test
 	public void annotationsIncludeHost() {