SpringCloud/spring-cloud-sleuth
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

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

Browse Source 
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
This commit is contained in:
Adrian Cole
2016-11-06 21:35:20 +08:00
parent 3ad22cd163
commit 903a9da226
4 changed files with 79 additions and 24 deletions
Download Patch File Download Diff File Expand all files Collapse all files

14
spring-cloud-sleuth-zipkin-stream/src/main/java/org/springframework/cloud/sleuth/zipkin/stream/ConvertToZipkinSpanList.java
View File

@@ -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;
}
}
}

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

@@ -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");
}
}
}

12
spring-cloud-sleuth-zipkin/src/main/java/org/springframework/cloud/sleuth/zipkin/ZipkinSpanListener.java
View File

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

49
spring-cloud-sleuth-zipkin/src/test/java/org/springframework/cloud/sleuth/zipkin/ZipkinSpanListenerTests.java
View File

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