diff --git a/spring-cloud-sleuth-zipkin-stream/src/main/java/org/springframework/cloud/sleuth/zipkin/stream/ConvertToZipkinSpanList.java b/spring-cloud-sleuth-zipkin-stream/src/main/java/org/springframework/cloud/sleuth/zipkin/stream/ConvertToZipkinSpanList.java index 16fc039d8..7a1e2bd47 100644 --- a/spring-cloud-sleuth-zipkin-stream/src/main/java/org/springframework/cloud/sleuth/zipkin/stream/ConvertToZipkinSpanList.java +++ b/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; } -} \ No newline at end of file +} diff --git a/spring-cloud-sleuth-zipkin-stream/src/test/java/org/springframework/cloud/sleuth/zipkin/stream/ConvertToZipkinSpanListTests.java b/spring-cloud-sleuth-zipkin-stream/src/test/java/org/springframework/cloud/sleuth/zipkin/stream/ConvertToZipkinSpanListTests.java index 09635824d..4aa3cac91 100644 --- a/spring-cloud-sleuth-zipkin-stream/src/test/java/org/springframework/cloud/sleuth/zipkin/stream/ConvertToZipkinSpanListTests.java +++ b/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.emptyList(), id, true, true, + return new Span(1, 3, "message:" + name, id, Collections.emptyList(), id, remote, true, "process"); } -} \ No newline at end of file +} diff --git a/spring-cloud-sleuth-zipkin/src/main/java/org/springframework/cloud/sleuth/zipkin/ZipkinSpanListener.java b/spring-cloud-sleuth-zipkin/src/main/java/org/springframework/cloud/sleuth/zipkin/ZipkinSpanListener.java index 07815baab..116a876e4 100644 --- a/spring-cloud-sleuth-zipkin/src/main/java/org/springframework/cloud/sleuth/zipkin/ZipkinSpanListener.java +++ b/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) { diff --git a/spring-cloud-sleuth-zipkin/src/test/java/org/springframework/cloud/sleuth/zipkin/ZipkinSpanListenerTests.java b/spring-cloud-sleuth-zipkin/src/test/java/org/springframework/cloud/sleuth/zipkin/ZipkinSpanListenerTests.java index 58f016e97..a99e4d267 100644 --- a/spring-cloud-sleuth-zipkin/src/test/java/org/springframework/cloud/sleuth/zipkin/ZipkinSpanListenerTests.java +++ b/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() {