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.

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

@@ -114,7 +114,7 @@ public class MessagingApplicationTests extends AbstractIntegrationTest {
 		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 @@ final class ConvertToZipkinSpanList {
 		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 @@ final class ConvertToZipkinSpanList {
 		}
 		return null;
 	}
-}
+}

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

@@ -155,7 +155,7 @@ public class ConvertToZipkinSpanListTests {
 	/** 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 class ConvertToZipkinSpanListTests {
 				.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();
 
-	/** Sleuth timestamps are millisecond granularity while zipkin is microsecond. */
+	/**
+	 * 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 convertsTimestampAndDurationToMicroseconds() {
-		long start = System.currentTimeMillis();
-		this.span.logEvent("hystrix/retry"); // System.currentTimeMillis
-
+	public void doesntSetTimestampOrDurationWhenRemote() {
+		this.span.stop();
 		zipkin.Span result = ConvertToZipkinSpanList.convert(this.span, this.host);
 
 		assertThat(result.timestamp)
-				.isEqualTo(this.span.getBegin() * 1000);
+				.isNull();
 		assertThat(result.duration)
-				.isEqualTo((this.span.getEnd() - this.span.getBegin()) * 1000);
+				.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();
+		span.logEvent("hystrix/retry"); // System.currentTimeMillis
+
+		zipkin.Span result = ConvertToZipkinSpanList.convert(span, this.host);
+
+		assertThat(result.timestamp)
+				.isEqualTo(span.getBegin() * 1000);
+		assertThat(result.duration)
+				.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 @@ public class ZipkinSpanListener implements SpanReporter {
 		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 class ZipkinSpanListenerTests {
 	/** 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,29 +84,31 @@ public class ZipkinSpanListenerTests {
 	@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
@@ -112,6 +116,23 @@ public class ZipkinSpanListenerTests {
 				.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() {