From 903a9da226a8218e2baa4b0b89298affb6f2d4ef Mon Sep 17 00:00:00 2001 From: Adrian Cole Date: Sun, 6 Nov 2016 21:35:20 +0800 Subject: [PATCH] Ensures Span.timestamp/duration are not reported on remote spans 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. See https://github.com/openzipkin/openzipkin.github.io/issues/49 --- .../stream/ConvertToZipkinSpanList.java | 14 ++++-- .../stream/ConvertToZipkinSpanListTests.java | 28 +++++++++-- .../sleuth/zipkin/ZipkinSpanListener.java | 12 +++-- .../zipkin/ZipkinSpanListenerTests.java | 49 +++++++++++++------ 4 files changed, 79 insertions(+), 24 deletions(-) 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() {