Ensures Span.timestamp/duration are not reported on remote spans

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() {