From b47bfe7fcb31343bb1fe9e3bd79c8f2be0fa35e1 Mon Sep 17 00:00:00 2001 From: Adrian Cole Date: Sun, 6 Nov 2016 19:38:46 +0800 Subject: [PATCH 1/6] Updates to zipkin 1.14.4 (#441) * Support for MySQL 5.7 with SQL_MODE=ONLY_FULL_GROUP_BY * Includes support to store 128-bit trace ID (not yet implemented here) See https://github.com/openzipkin/b3-propagation/issues/6 --- spring-cloud-sleuth-dependencies/pom.xml | 4 ++-- spring-cloud-sleuth-samples/pom.xml | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) 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 From cd2b0fd0f4be38387cd53534dc9591b1917eb74c Mon Sep 17 00:00:00 2001 From: Christoffer Sawicki Date: Sun, 6 Nov 2016 20:03:34 +0100 Subject: [PATCH 2/6] Allow TraceWebAutoConfiguration to work without Web MVC Fixes #436 --- .../instrument/web/TraceWebAutoConfiguration.java | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) 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); From 57f95aac3e26c97e996686cacc516afe11f59633 Mon Sep 17 00:00:00 2001 From: Marcin Grzejszczak Date: Sun, 6 Nov 2016 10:06:17 +0100 Subject: [PATCH 3/6] Added a test for tracing the tracer --- spring-cloud-sleuth-stream/pom.xml | 5 + .../stream/StreamSpanListenerTests.java | 8 +- .../TraceIgnoringChannelInterceptorTests.java | 105 ++++++++++++++++++ 3 files changed, 116 insertions(+), 2 deletions(-) create mode 100644 spring-cloud-sleuth-stream/src/test/java/org/springframework/cloud/sleuth/stream/TraceIgnoringChannelInterceptorTests.java 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..3d7e395ea --- /dev/null +++ b/spring-cloud-sleuth-stream/src/test/java/org/springframework/cloud/sleuth/stream/TraceIgnoringChannelInterceptorTests.java @@ -0,0 +1,105 @@ +/* + * 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.boot.test.context.SpringBootTest; +import org.springframework.boot.test.context.SpringBootTest.WebEnvironment; +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(); + } + } +} From cec661e8c674e867aaf871ab3b5a347186549f19 Mon Sep 17 00:00:00 2001 From: Marcin Grzejszczak Date: Sun, 6 Nov 2016 22:45:06 +0100 Subject: [PATCH 4/6] Removed wrong imports --- .../sleuth/stream/TraceIgnoringChannelInterceptorTests.java | 2 -- 1 file changed, 2 deletions(-) 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 index 3d7e395ea..01485ff4d 100644 --- 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 @@ -26,8 +26,6 @@ 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.boot.test.context.SpringBootTest; -import org.springframework.boot.test.context.SpringBootTest.WebEnvironment; import org.springframework.cloud.sleuth.Sampler; import org.springframework.cloud.sleuth.Span; import org.springframework.cloud.sleuth.Tracer; From 81d5361561b76d4472ae84bf3246a27b4f2d6e11 Mon Sep 17 00:00:00 2001 From: Adrian Cole Date: Mon, 7 Nov 2016 06:58:08 -0800 Subject: [PATCH 5/6] Ensures Span.timestamp/duration are not reported on remote spans (#443) 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. --- .../MessagingApplicationTests.java | 2 +- .../stream/ConvertToZipkinSpanList.java | 14 ++++-- .../stream/ConvertToZipkinSpanListTests.java | 28 +++++++++-- .../stream/ZipkinMessageListenerTests.java | 33 ++++++++++--- .../sleuth/zipkin/ZipkinSpanListener.java | 12 +++-- .../zipkin/ZipkinSpanListenerTests.java | 49 +++++++++++++------ 6 files changed, 106 insertions(+), 32 deletions(-) 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-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() { From 54932c567501cf277b3363d93e07691f2c0e85c8 Mon Sep 17 00:00:00 2001 From: Marcin Grzejszczak Date: Tue, 8 Nov 2016 15:05:06 +0100 Subject: [PATCH 6/6] Wrapping ExecutorService in its own representation without this change ExecutorService was treated as an Executor and wrapped in the Executor bean. Due to this the bean was missing / bean of invalid type was registered. with this change we do not wrap ExecutorService with a Executor bean, instead we wrap it in a TraceableExecutorService representation. fixes #445 --- README.adoc | 4 +- .../async/TraceExecutorBeanPostProcessor.java | 6 +- .../async/TraceableExecutorService.java | 57 ++++++++++++++----- .../async/issues/issue410/Issue410Tests.java | 26 ++++++++- 4 files changed, 74 insertions(+), 19 deletions(-) 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/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(); + } + }