diff --git a/spring-cloud-sleuth-samples/spring-cloud-sleuth-sample-messaging/src/test/java/integration/MessagingApplicationTests.java b/spring-cloud-sleuth-samples/spring-cloud-sleuth-sample-messaging/src/test/java/integration/MessagingApplicationTests.java index 81f5174e0c..b8ccb31235 100644 --- a/spring-cloud-sleuth-samples/spring-cloud-sleuth-sample-messaging/src/test/java/integration/MessagingApplicationTests.java +++ b/spring-cloud-sleuth-samples/spring-cloud-sleuth-sample-messaging/src/test/java/integration/MessagingApplicationTests.java @@ -114,7 +114,7 @@ private void thenTheSpansHaveProperParentStructure() { Optional eventReceivedSpan = findSpanWithAnnotation(Constants.CLIENT_RECV); Optional 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"); 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 16fc039d88..7a1e2bd473 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 @@ 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; } -} \ 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 09635824d1..4aa3cac913 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 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.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-stream/src/test/java/org/springframework/cloud/sleuth/zipkin/stream/ZipkinMessageListenerTests.java b/spring-cloud-sleuth-zipkin-stream/src/test/java/org/springframework/cloud/sleuth/zipkin/stream/ZipkinMessageListenerTests.java index cab8523df7..31d94b3ecf 100644 --- a/spring-cloud-sleuth-zipkin-stream/src/test/java/org/springframework/cloud/sleuth/zipkin/stream/ZipkinMessageListenerTests.java +++ b/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.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); 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 07815baab3..116a876e41 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 @@ 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) { 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 58f016e97b..a99e4d2672 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 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,29 +84,31 @@ 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 @@ -112,6 +116,23 @@ 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() { + 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() {