diff --git a/README.adoc b/README.adoc index c4f9b28fb..7fa260c97 100644 --- a/README.adoc +++ b/README.adoc @@ -598,11 +598,11 @@ a modified file in the correct place. Just commit it and push the change. If you don't have an IDE preference we would recommend that you use http://www.springsource.com/developer/sts[Spring Tools Suite] or http://eclipse.org[Eclipse] when working with the code. We use the -http://eclipse.org/m2e/[m2eclipe] eclipse plugin for maven support. Other IDEs and tools +http://eclipse.org/m2e/[m2eclipse] eclipse plugin for maven support. Other IDEs and tools should also work without issue as long as they use Maven 3.3.3 or better. ==== Importing into eclipse with m2eclipse -We recommend the http://eclipse.org/m2e/[m2eclipe] eclipse plugin when working with +We recommend the http://eclipse.org/m2e/[m2eclipse] eclipse plugin when working with eclipse. If you don't already have m2eclipse installed it is available from the "eclipse marketplace". diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/async/TraceExecutorBeanPostProcessor.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/async/TraceExecutorBeanPostProcessor.java index 04e8ea0ef..3d59e9e48 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/async/TraceExecutorBeanPostProcessor.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/async/TraceExecutorBeanPostProcessor.java @@ -17,6 +17,7 @@ package org.springframework.cloud.sleuth.instrument.async; import java.util.concurrent.Executor; +import java.util.concurrent.ExecutorService; import org.springframework.beans.BeansException; import org.springframework.beans.factory.BeanFactory; @@ -43,8 +44,11 @@ class TraceExecutorBeanPostProcessor implements BeanPostProcessor { if (bean instanceof ThreadPoolTaskExecutor && !(bean instanceof TaskScheduler) && !(bean instanceof LazyTraceThreadPoolTaskExecutor)) { return new LazyTraceThreadPoolTaskExecutor(this.beanFactory, (ThreadPoolTaskExecutor) bean); - } else if (bean instanceof Executor && !(bean instanceof TaskScheduler) && !(bean instanceof LazyTraceExecutor)) { + } else if (bean instanceof Executor && !(bean instanceof ExecutorService) && + !(bean instanceof TaskScheduler) && !(bean instanceof LazyTraceExecutor)) { return new LazyTraceExecutor(this.beanFactory, (Executor) bean); + } else if (bean instanceof ExecutorService) { + return new TraceableExecutorService(this.beanFactory, (ExecutorService) bean); } return bean; } diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/async/TraceableExecutorService.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/async/TraceableExecutorService.java index 4bd0d578e..fbf547f28 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/async/TraceableExecutorService.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/async/TraceableExecutorService.java @@ -25,6 +25,7 @@ import java.util.concurrent.Future; import java.util.concurrent.TimeUnit; import java.util.concurrent.TimeoutException; +import org.springframework.beans.factory.BeanFactory; import org.springframework.cloud.sleuth.SpanNamer; import org.springframework.cloud.sleuth.TraceKeys; import org.springframework.cloud.sleuth.Tracer; @@ -36,17 +37,24 @@ import org.springframework.cloud.sleuth.Tracer; * @since 1.0.0 */ public class TraceableExecutorService implements ExecutorService { - final ExecutorService delegate; - final Tracer tracer; + ExecutorService delegate; + Tracer tracer; private final String spanName; - final TraceKeys traceKeys; - final SpanNamer spanNamer; + TraceKeys traceKeys; + SpanNamer spanNamer; + BeanFactory beanFactory; public TraceableExecutorService(final ExecutorService delegate, final Tracer tracer, TraceKeys traceKeys, SpanNamer spanNamer) { this(delegate, tracer, traceKeys, spanNamer, null); } + public TraceableExecutorService(BeanFactory beanFactory, final ExecutorService delegate) { + this.delegate = delegate; + this.beanFactory = beanFactory; + this.spanName = null; + } + public TraceableExecutorService(final ExecutorService delegate, final Tracer tracer, TraceKeys traceKeys, SpanNamer spanNamer, String spanName) { this.delegate = delegate; @@ -58,8 +66,8 @@ public class TraceableExecutorService implements ExecutorService { @Override public void execute(Runnable command) { - final Runnable r = new LocalComponentTraceRunnable(this.tracer, this.traceKeys, - this.spanNamer, command, this.spanName); + final Runnable r = new LocalComponentTraceRunnable(tracer(), traceKeys(), + spanNamer(), command, this.spanName); this.delegate.execute(r); } @@ -90,22 +98,22 @@ public class TraceableExecutorService implements ExecutorService { @Override public Future submit(Callable task) { - Callable c = new LocalComponentTraceCallable<>(this.tracer, this.traceKeys, - this.spanNamer, this.spanName, task); + Callable c = new LocalComponentTraceCallable<>(tracer(), traceKeys(), + spanNamer(), this.spanName, task); return this.delegate.submit(c); } @Override public Future submit(Runnable task, T result) { - Runnable r = new LocalComponentTraceRunnable(this.tracer, this.traceKeys, - this.spanNamer, task, this.spanName); + Runnable r = new LocalComponentTraceRunnable(tracer(), traceKeys(), + spanNamer(), task, this.spanName); return this.delegate.submit(r, result); } @Override public Future submit(Runnable task) { - Runnable r = new LocalComponentTraceRunnable(this.tracer, this.traceKeys, - this.spanNamer, task, this.spanName); + Runnable r = new LocalComponentTraceRunnable(tracer(), traceKeys(), + spanNamer(), task, this.spanName); return this.delegate.submit(r); } @@ -135,11 +143,32 @@ public class TraceableExecutorService implements ExecutorService { List> ts = new ArrayList<>(); for (Callable task : tasks) { if (!(task instanceof LocalComponentTraceCallable)) { - ts.add(new LocalComponentTraceCallable<>(this.tracer, this.traceKeys, - this.spanNamer, this.spanName, task)); + ts.add(new LocalComponentTraceCallable<>(tracer(), traceKeys(), + spanNamer(), this.spanName, task)); } } return ts; } + Tracer tracer() { + if (this.tracer == null && this.beanFactory != null) { + this.tracer = this.beanFactory.getBean(Tracer.class); + } + return this.tracer; + } + + TraceKeys traceKeys() { + if (this.traceKeys == null && this.beanFactory != null) { + this.traceKeys = this.beanFactory.getBean(TraceKeys.class); + } + return this.traceKeys; + } + + SpanNamer spanNamer() { + if (this.spanNamer == null && this.beanFactory != null) { + this.spanNamer = this.beanFactory.getBean(SpanNamer.class); + } + return this.spanNamer; + } + } diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceWebAutoConfiguration.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceWebAutoConfiguration.java index 43117dae3..0c5e0a590 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceWebAutoConfiguration.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceWebAutoConfiguration.java @@ -40,6 +40,7 @@ import org.springframework.context.annotation.Bean; import org.springframework.context.annotation.Configuration; import org.springframework.context.annotation.Import; import org.springframework.util.StringUtils; +import org.springframework.web.servlet.config.annotation.WebMvcConfigurerAdapter; import static javax.servlet.DispatcherType.ASYNC; import static javax.servlet.DispatcherType.ERROR; @@ -63,7 +64,6 @@ import static javax.servlet.DispatcherType.REQUEST; @ConditionalOnBean(Tracer.class) @AutoConfigureAfter(TraceAutoConfiguration.class) @EnableConfigurationProperties(TraceKeys.class) -@Import(TraceWebMvcConfigurer.class) public class TraceWebAutoConfiguration { /** @@ -72,6 +72,16 @@ public class TraceWebAutoConfiguration { @Value("${spring.sleuth.web.skipPattern:}") private String skipPattern; + /** + * Nested config that configures Web MVC if it's present + * (without adding a runtime dependency to it) + */ + @Configuration + @ConditionalOnClass(WebMvcConfigurerAdapter.class) + @Import(TraceWebMvcConfigurer.class) + protected static class TraceWebMvcAutoConfiguration { + } + @Bean public TraceWebAspect traceWebAspect(Tracer tracer, SpanNamer spanNamer) { return new TraceWebAspect(tracer, spanNamer); diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/async/issues/issue410/Issue410Tests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/async/issues/issue410/Issue410Tests.java index dd3c17a08..1c8e3b283 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/async/issues/issue410/Issue410Tests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/async/issues/issue410/Issue410Tests.java @@ -19,6 +19,8 @@ package org.springframework.cloud.sleuth.instrument.async.issues.issue410; import java.util.concurrent.CompletableFuture; import java.util.concurrent.ExecutionException; import java.util.concurrent.Executor; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; import java.util.concurrent.atomic.AtomicReference; import org.apache.commons.logging.Log; @@ -36,6 +38,7 @@ import org.springframework.cloud.sleuth.Sampler; import org.springframework.cloud.sleuth.Span; import org.springframework.cloud.sleuth.Tracer; import org.springframework.cloud.sleuth.instrument.async.LazyTraceExecutor; +import org.springframework.cloud.sleuth.instrument.async.TraceableExecutorService; import org.springframework.cloud.sleuth.sampler.AlwaysSampler; import org.springframework.context.annotation.Bean; import org.springframework.context.annotation.Configuration; @@ -67,6 +70,10 @@ public class Issue410Tests { @Autowired Tracer tracer; @Autowired AsyncTask asyncTask; @Autowired RestTemplate restTemplate; + /** + * Related to issue #445 + */ + @Autowired ExecutorService executorService; @Test public void should_pass_tracing_info_for_tasks_running_without_a_pool() { @@ -138,6 +145,14 @@ public class Issue410Tests { } } + /** + * Related to issue #445 + */ + @Test + public void should_wrap_executor_service_in_trace_representation() { + then(this.executorService).isInstanceOf(TraceableExecutorService.class); + } + private int port() { return this.environment.getProperty("local.server.port", Integer.class); } @@ -148,11 +163,11 @@ public class Issue410Tests { @EnableAsync class AppConfig { - @Bean Sampler testSampler() { + @Bean public Sampler testSampler() { return new AlwaysSampler(); } - @Bean RestTemplate restTemplate() { + @Bean public RestTemplate restTemplate() { return new RestTemplate(); } @@ -281,4 +296,11 @@ class Application { return Span.idToHex(this.asyncTask.taskScheduler().getTraceId()); } + /** + * Related to issue #445 + */ + @Bean public ExecutorService executorService() { + return Executors.newSingleThreadExecutor(); + } + } diff --git a/spring-cloud-sleuth-dependencies/pom.xml b/spring-cloud-sleuth-dependencies/pom.xml index 7bf2ee6e7..fe99ab3a7 100644 --- a/spring-cloud-sleuth-dependencies/pom.xml +++ b/spring-cloud-sleuth-dependencies/pom.xml @@ -14,8 +14,8 @@ spring-cloud-sleuth-dependencies Spring Cloud Sleuth Dependencies - 1.13.1 - 0.6.1 + 1.14.4 + 0.6.6 diff --git a/spring-cloud-sleuth-samples/pom.xml b/spring-cloud-sleuth-samples/pom.xml index d87a6b0e9..0960508e2 100644 --- a/spring-cloud-sleuth-samples/pom.xml +++ b/spring-cloud-sleuth-samples/pom.xml @@ -59,12 +59,12 @@ io.zipkin.java zipkin - 1.13.1 + 1.14.4 io.zipkin.java zipkin-server - 1.13.1 + 1.14.4 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 81f5174e0..b8ccb3123 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 @@ public class MessagingApplicationTests extends AbstractIntegrationTest { 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-stream/pom.xml b/spring-cloud-sleuth-stream/pom.xml index 9a756a4ca..a781bd524 100644 --- a/spring-cloud-sleuth-stream/pom.xml +++ b/spring-cloud-sleuth-stream/pom.xml @@ -59,6 +59,11 @@ spring-boot-starter-test test + + org.aspectj + aspectjweaver + test + diff --git a/spring-cloud-sleuth-stream/src/test/java/org/springframework/cloud/sleuth/stream/StreamSpanListenerTests.java b/spring-cloud-sleuth-stream/src/test/java/org/springframework/cloud/sleuth/stream/StreamSpanListenerTests.java index cf41a4c9c..c99df54f0 100644 --- a/spring-cloud-sleuth-stream/src/test/java/org/springframework/cloud/sleuth/stream/StreamSpanListenerTests.java +++ b/spring-cloud-sleuth-stream/src/test/java/org/springframework/cloud/sleuth/stream/StreamSpanListenerTests.java @@ -84,8 +84,10 @@ public class StreamSpanListenerTests { @Test public void acquireAndRelease() { Span context = this.tracer.createSpan("http:foo"); + this.tracer.close(context); - assertEquals(1, this.test.spans.size()); + + assertThat(this.test.spans).hasSize(1); } @Test @@ -96,8 +98,10 @@ public class StreamSpanListenerTests { context.logEvent(Span.CLIENT_SEND); logServerReceived(parent); logServerSent(this.spanReporter, parent); + this.tracer.close(context); - assertEquals(2, this.test.spans.size()); + + assertThat(this.test.spans).hasSize(2); } void logServerReceived(Span parent) { diff --git a/spring-cloud-sleuth-stream/src/test/java/org/springframework/cloud/sleuth/stream/TraceIgnoringChannelInterceptorTests.java b/spring-cloud-sleuth-stream/src/test/java/org/springframework/cloud/sleuth/stream/TraceIgnoringChannelInterceptorTests.java new file mode 100644 index 000000000..01485ff4d --- /dev/null +++ b/spring-cloud-sleuth-stream/src/test/java/org/springframework/cloud/sleuth/stream/TraceIgnoringChannelInterceptorTests.java @@ -0,0 +1,103 @@ +/* + * Copyright 2013-2015 the original author or authors. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.springframework.cloud.sleuth.stream; + +import javax.annotation.PostConstruct; +import java.util.concurrent.BlockingQueue; +import java.util.concurrent.LinkedBlockingQueue; + +import org.junit.After; +import org.junit.Before; +import org.junit.Test; +import org.junit.runner.RunWith; +import org.springframework.beans.factory.annotation.Autowired; +import org.springframework.boot.autoconfigure.EnableAutoConfiguration; +import org.springframework.cloud.sleuth.Sampler; +import org.springframework.cloud.sleuth.Span; +import org.springframework.cloud.sleuth.Tracer; +import org.springframework.cloud.sleuth.sampler.AlwaysSampler; +import org.springframework.cloud.sleuth.util.ExceptionUtils; +import org.springframework.context.annotation.Bean; +import org.springframework.context.annotation.Configuration; +import org.springframework.integration.core.MessagingTemplate; +import org.springframework.integration.support.MessageBuilder; +import org.springframework.test.annotation.DirtiesContext; +import org.springframework.test.context.ContextConfiguration; +import org.springframework.test.context.junit4.SpringJUnit4ClassRunner; + +import static org.assertj.core.api.BDDAssertions.then; + +/** + * @author Dave Syer + */ +@RunWith(SpringJUnit4ClassRunner.class) +@ContextConfiguration(classes = TraceIgnoringChannelInterceptorTests.App.class) +@DirtiesContext +public class TraceIgnoringChannelInterceptorTests { + + @Autowired Tracer tracer; + @Autowired App app; + @Autowired MessagingTemplate messagingTemplate; + + @Before + public void init() { + this.app.clear(); + } + + @After + public void close() { + then(ExceptionUtils.getLastException()).isNull(); + this.app.clear(); + } + + @Test + public void shouldNotTraceTheTracer() { + this.messagingTemplate.send(MessageBuilder.withPayload("hi").build()); + + Spans spans = this.app.listener.poll(); + + then(spans).isNull(); + then(this.tracer.getCurrentSpan()).isNull(); + } + + @Configuration + @EnableAutoConfiguration + static class App { + + private final BlockingQueue spans = new LinkedBlockingQueue<>(); + + @Autowired StreamSpanReporter listener; + + @Bean MessagingTemplate messagingTemplate(SleuthSource sleuthSource) { + return new MessagingTemplate(sleuthSource.output()); + } + + @Bean Sampler alwaysSampler() { + return new AlwaysSampler(); + } + + + @PostConstruct + public void init() { + this.listener.setQueue(this.spans); + } + + public void clear() { + this.spans.clear(); + } + } +} 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-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 cab8523df..31d94b3ec 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(); - /** Sleuth timestamps are millisecond granularity while zipkin is microsecond. */ + /** + * 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 convertsTimestampAndDurationToMicroseconds() { - long start = System.currentTimeMillis(); - this.span.logEvent("hystrix/retry"); // System.currentTimeMillis - + public void doesntSetTimestampOrDurationWhenRemote() { + this.span.stop(); zipkin.Span result = ConvertToZipkinSpanList.convert(this.span, this.host); assertThat(result.timestamp) - .isEqualTo(this.span.getBegin() * 1000); + .isNull(); assertThat(result.duration) - .isEqualTo((this.span.getEnd() - this.span.getBegin()) * 1000); + .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(); + span.logEvent("hystrix/retry"); // System.currentTimeMillis + + zipkin.Span result = ConvertToZipkinSpanList.convert(span, this.host); + + assertThat(result.timestamp) + .isEqualTo(span.getBegin() * 1000); + assertThat(result.duration) + .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 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() {