From 9e01d774314f947d37a4cd5dcf4ddabe6f70a157 Mon Sep 17 00:00:00 2001 From: Marcin Grzejszczak Date: Thu, 8 Sep 2016 22:06:44 +0200 Subject: [PATCH] Feign fixes it turned out that some of the tests were leaky and didn't catch that ExceptionUtils were throwing an exception (race condition with Hystrix). That was due to the fact that When Hystrix with Feign were doing retries the RequestInterceptor wasn't called. That means that a new span wasn't created but a parent span was closed. With this change the only place where the span creation and closing takes place is TraceFeignClient. I removed the Feign RequestInterceptor. Now whenever there is a retry - a new span is created and closed after getting a response. There are no exceptions, special cases etc. In addition to that since Feign is fully immutable and SpanInjector is by design made to mutate objects I had to wrap the immutable Request in an AtomicReference in order to change the contents of the Request. I'm ashamed but didn't have a better idea. Since that is packaged scope nobody should every see that (outside the package of course) --- spring-cloud-sleuth-core/pom.xml | 6 ++ .../SleuthHystrixConcurrencyStrategy.java | 27 +++++-- .../sleuth/instrument/web/TraceFilter.java | 2 +- .../client/feign/FeignRequestInjector.java | 79 +++++++++++++++++++ .../feign/FeignRequestTemplateInjector.java | 61 -------------- .../web/client/feign/TraceFeignClient.java | 34 ++++++-- .../TraceFeignClientAutoConfiguration.java | 10 --- .../feign/TraceFeignRequestInterceptor.java | 63 --------------- .../feign/TraceLoadBalancerFeignClient.java | 20 +---- .../exception/WebClientExceptionTests.java | 16 +++- .../web/client/feign/FeignRetriesTests.java | 18 ++--- .../client/feign/TraceFeignClientTests.java | 8 +- .../sleuth/stream/StreamSpanReporter.java | 9 +++ .../sleuth/zipkin/ZipkinSpanListener.java | 4 + 14 files changed, 176 insertions(+), 181 deletions(-) create mode 100644 spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/FeignRequestInjector.java delete mode 100644 spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/FeignRequestTemplateInjector.java delete mode 100644 spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignRequestInterceptor.java diff --git a/spring-cloud-sleuth-core/pom.xml b/spring-cloud-sleuth-core/pom.xml index 178facd82..b08f90051 100644 --- a/spring-cloud-sleuth-core/pom.xml +++ b/spring-cloud-sleuth-core/pom.xml @@ -146,6 +146,12 @@ spring-cloud-starter-eureka test + + com.github.stefanbirkner + system-rules + 1.16.0 + test + diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/hystrix/SleuthHystrixConcurrencyStrategy.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/hystrix/SleuthHystrixConcurrencyStrategy.java index 9878b44fa..544f43e0b 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/hystrix/SleuthHystrixConcurrencyStrategy.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/hystrix/SleuthHystrixConcurrencyStrategy.java @@ -16,14 +16,9 @@ package org.springframework.cloud.sleuth.instrument.hystrix; +import java.lang.invoke.MethodHandles; import java.util.concurrent.Callable; -import org.apache.commons.logging.Log; -import org.apache.commons.logging.LogFactory; -import org.springframework.cloud.sleuth.Span; -import org.springframework.cloud.sleuth.TraceKeys; -import org.springframework.cloud.sleuth.Tracer; - import com.netflix.hystrix.strategy.HystrixPlugins; import com.netflix.hystrix.strategy.concurrency.HystrixConcurrencyStrategy; import com.netflix.hystrix.strategy.eventnotifier.HystrixEventNotifier; @@ -31,6 +26,12 @@ import com.netflix.hystrix.strategy.executionhook.HystrixCommandExecutionHook; import com.netflix.hystrix.strategy.metrics.HystrixMetricsPublisher; import com.netflix.hystrix.strategy.properties.HystrixPropertiesStrategy; +import org.apache.commons.logging.Log; +import org.apache.commons.logging.LogFactory; +import org.springframework.cloud.sleuth.Span; +import org.springframework.cloud.sleuth.TraceKeys; +import org.springframework.cloud.sleuth.Tracer; + /** * A {@link HystrixConcurrencyStrategy} that wraps a {@link Callable} in a * {@link Callable} that either starts a new span or continues one if the tracing was @@ -109,6 +110,8 @@ public class SleuthHystrixConcurrencyStrategy extends HystrixConcurrencyStrategy // Visible for testing static class HystrixTraceCallable implements Callable { + private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass()); + private Tracer tracer; private TraceKeys traceKeys; private Callable callable; @@ -128,10 +131,16 @@ public class SleuthHystrixConcurrencyStrategy extends HystrixConcurrencyStrategy boolean created = false; if (span != null) { span = this.tracer.continueSpan(span); + if (log.isDebugEnabled()) { + log.debug("Continuing span " + span); + } } else { span = this.tracer.createSpan(HYSTRIX_COMPONENT); created = true; + if (log.isDebugEnabled()) { + log.debug("Creating new span " + span); + } } if (!span.tags().containsKey(Span.SPAN_LOCAL_COMPONENT_TAG_NAME)) { this.tracer.addTag(Span.SPAN_LOCAL_COMPONENT_TAG_NAME, HYSTRIX_COMPONENT); @@ -146,9 +155,15 @@ public class SleuthHystrixConcurrencyStrategy extends HystrixConcurrencyStrategy } finally { if (created) { + if (log.isDebugEnabled()) { + log.debug("Closing span since it was created" + span); + } this.tracer.close(span); } else { + if (log.isDebugEnabled()) { + log.debug("Detaching span since it was continued " + span); + } this.tracer.detach(span); } } diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceFilter.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceFilter.java index cf32f75de..e5222e2cc 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceFilter.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceFilter.java @@ -241,7 +241,7 @@ public class TraceFilter extends GenericFilterBean { } if (parent.isRemote()) { if (log.isDebugEnabled()) { - log.debug("Sending the parent span " + parent + " to Zipkin"); + log.debug("Trying to send the parent span " + parent + " to Zipkin"); } parent.stop(); parent.logEvent(Span.SERVER_SEND); diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/FeignRequestInjector.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/FeignRequestInjector.java new file mode 100644 index 000000000..f1323a35e --- /dev/null +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/FeignRequestInjector.java @@ -0,0 +1,79 @@ +/* + * Copyright 2013-2016 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.instrument.web.client.feign; + +import java.nio.charset.Charset; +import java.util.ArrayList; +import java.util.Collection; +import java.util.HashMap; +import java.util.List; +import java.util.Map; +import java.util.concurrent.atomic.AtomicReference; + +import org.springframework.cloud.sleuth.Span; +import org.springframework.cloud.sleuth.SpanInjector; +import org.springframework.util.StringUtils; + +import feign.Request; + +/** + * Span injector that injects tracing info to {@link Request} via {@link AtomicReference} + * since {@link Request} is immutable. + * + * @author Marcin Grzejszczak + * + * @since 1.0.0 + */ +class FeignRequestInjector implements SpanInjector> { + + @Override + public void inject(Span span, AtomicReference carrier) { + String method = carrier.get().method(); + String url = carrier.get().url(); + Map> headers = new HashMap<>(carrier.get().headers()); + byte[] body = carrier.get().body(); + Charset charset = carrier.get().charset(); + if (span == null) { + setHeader(headers, Span.SAMPLED_NAME, Span.SPAN_NOT_SAMPLED); + carrier.set(Request.create(method, url, headers, body, charset)); + return; + } + setHeader(headers, Span.TRACE_ID_NAME, Span.idToHex(span.getTraceId())); + setHeader(headers, Span.SPAN_NAME_NAME, span.getName()); + setHeader(headers, Span.SPAN_ID_NAME, Span.idToHex(span.getSpanId())); + setHeader(headers, Span.SAMPLED_NAME, span.isExportable() ? + Span.SPAN_SAMPLED : Span.SPAN_NOT_SAMPLED); + Long parentId = getParentId(span); + if (parentId != null) { + setHeader(headers, Span.PARENT_ID_NAME, Span.idToHex(parentId)); + } + setHeader(headers, Span.PROCESS_ID_NAME, span.getProcessId()); + carrier.set(Request.create(method, url, headers, body, charset)); + } + + private Long getParentId(Span span) { + return !span.getParents().isEmpty() ? span.getParents().get(0) : null; + } + + protected void setHeader(Map> headers, String name, String value) { + if (StringUtils.hasText(value) && !headers.containsKey(name)) { + List list = new ArrayList<>(); + list.add(value); + headers.put(name, list); + } + } +} diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/FeignRequestTemplateInjector.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/FeignRequestTemplateInjector.java deleted file mode 100644 index 118927f5b..000000000 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/FeignRequestTemplateInjector.java +++ /dev/null @@ -1,61 +0,0 @@ -/* - * Copyright 2013-2016 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.instrument.web.client.feign; - -import org.springframework.cloud.sleuth.Span; -import org.springframework.cloud.sleuth.SpanInjector; -import org.springframework.util.StringUtils; - -import feign.RequestTemplate; - -/** - * Span injector that injects tracing info to {@link RequestTemplate} - * - * @author Marcin Grzejszczak - * - * @since 1.0.0 - */ -class FeignRequestTemplateInjector implements SpanInjector { - - @Override - public void inject(Span span, RequestTemplate carrier) { - if (span == null) { - setHeader(carrier, Span.SAMPLED_NAME, Span.SPAN_NOT_SAMPLED); - return; - } - carrier.header(Span.TRACE_ID_NAME, Span.idToHex(span.getTraceId())); - setHeader(carrier, Span.SPAN_NAME_NAME, span.getName()); - setHeader(carrier, Span.SPAN_ID_NAME, Span.idToHex(span.getSpanId())); - setHeader(carrier, Span.SAMPLED_NAME, span.isExportable() ? - Span.SPAN_SAMPLED : Span.SPAN_NOT_SAMPLED); - Long parentId = getParentId(span); - if (parentId != null) { - setHeader(carrier, Span.PARENT_ID_NAME, Span.idToHex(parentId)); - } - setHeader(carrier, Span.PROCESS_ID_NAME, span.getProcessId()); - } - - private Long getParentId(Span span) { - return !span.getParents().isEmpty() ? span.getParents().get(0) : null; - } - - protected void setHeader(RequestTemplate request, String name, String value) { - if (StringUtils.hasText(value) && !request.headers().containsKey(name)) { - request.header(name, value); - } - } -} diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClient.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClient.java index fa9e85df3..1c66c0108 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClient.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClient.java @@ -19,6 +19,7 @@ package org.springframework.cloud.sleuth.instrument.web.client.feign; import java.io.IOException; import java.lang.invoke.MethodHandles; import java.net.URI; +import java.util.concurrent.atomic.AtomicReference; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; @@ -39,7 +40,7 @@ import feign.Response; * * @since 1.0.0 */ -final class TraceFeignClient implements Client { +class TraceFeignClient implements Client { private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass()); @@ -47,6 +48,7 @@ final class TraceFeignClient implements Client { private HttpTraceKeysInjector keysInjector; private final BeanFactory beanFactory; private Tracer tracer; + private final FeignRequestInjector spanInjector = new FeignRequestInjector(); TraceFeignClient(BeanFactory beanFactory) { this.beanFactory = beanFactory; @@ -60,19 +62,40 @@ final class TraceFeignClient implements Client { @Override public Response execute(Request request, Request.Options options) throws IOException { + String spanName = getSpanName(request); + Span span = getTracer().createSpan(spanName); + if (log.isDebugEnabled()) { + log.debug("Created new Feign span " + span); + } try { + AtomicReference feignRequest = new AtomicReference<>(request); + this.spanInjector.inject(span, feignRequest); + span.logEvent(Span.CLIENT_SEND); addRequestTags(request); - Response response = this.delegate.execute(request, options); + Request modifiedRequest = feignRequest.get(); + if (log.isDebugEnabled()) { + log.debug("The modified request equals " + modifiedRequest); + } + Response response = this.delegate.execute(modifiedRequest, options); logCr(); return response; } catch (RuntimeException | IOException e) { logError(e); throw e; } finally { - closeSpan(); + closeSpan(span); } } + private String getSpanName(Request request) { + URI uri = URI.create(request.url()); + return uriScheme(uri) + ":" + uri.getPath(); + } + + private String uriScheme(URI uri) { + return uri.getScheme() == null ? "http" : uri.getScheme(); + } + /** * Adds HTTP tags to the client side span */ @@ -89,8 +112,7 @@ final class TraceFeignClient implements Client { return this.keysInjector; } - private void closeSpan() { - Span span = getTracer().getCurrentSpan(); + private void closeSpan(Span span) { if (span != null) { if (log.isDebugEnabled()) { log.debug("Closing Feign span " + span); @@ -103,7 +125,7 @@ final class TraceFeignClient implements Client { Span span = getTracer().getCurrentSpan(); if (span != null) { if (log.isDebugEnabled()) { - log.debug("Closing Feign span and logging CR" + span); + log.debug("Closing Feign span and logging CR " + span); } span.logEvent(Span.CLIENT_RECV); } diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClientAutoConfiguration.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClientAutoConfiguration.java index 10da31b1b..6595fefa2 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClientAutoConfiguration.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClientAutoConfiguration.java @@ -32,7 +32,6 @@ import org.springframework.context.annotation.Scope; import feign.Client; import feign.Feign; -import feign.RequestInterceptor; /** * {@link org.springframework.boot.autoconfigure.EnableAutoConfiguration @@ -84,13 +83,4 @@ public class TraceFeignClientAutoConfiguration { TraceFeignObjectWrapper traceFeignObjectWrapper(BeanFactory beanFactory) { return new TraceFeignObjectWrapper(beanFactory); } - - /** - * Sleuth {@link feign.RequestInterceptor} that either starts a new Span or continues - * an existing one if a retry takes place. - */ - @Bean - RequestInterceptor traceIdRequestInterceptor(Tracer tracer) { - return new TraceFeignRequestInterceptor(tracer, new FeignRequestTemplateInjector()); - } } diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignRequestInterceptor.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignRequestInterceptor.java deleted file mode 100644 index 425e5bda6..000000000 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignRequestInterceptor.java +++ /dev/null @@ -1,63 +0,0 @@ -/* - * Copyright 2013-2016 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.instrument.web.client.feign; - -import java.net.URI; - -import org.springframework.cloud.sleuth.Span; -import org.springframework.cloud.sleuth.SpanInjector; -import org.springframework.cloud.sleuth.Tracer; - -import feign.RequestInterceptor; -import feign.RequestTemplate; - -/** - * A request interceptor that sets tracing information in the headers. - * - * @author Marcin Grzejszczak - * - * @since 1.0.0 - */ -final class TraceFeignRequestInterceptor implements RequestInterceptor { - - private final Tracer tracer; - private final SpanInjector spanInjector; - - TraceFeignRequestInterceptor(Tracer tracer, - SpanInjector spanInjector) { - this.tracer = tracer; - this.spanInjector = spanInjector; - } - - @Override - public void apply(RequestTemplate template) { - String spanName = getSpanName(template); - Span span = this.tracer.createSpan(spanName); - this.spanInjector.inject(span, template); - span.logEvent(Span.CLIENT_SEND); - } - - private String getSpanName(RequestTemplate template) { - URI uri = URI.create(template.url()); - return uriScheme(uri) + ":" + uri.getPath(); - } - - private String uriScheme(URI uri) { - return uri.getScheme() == null ? "http" : uri.getScheme(); - } - -} diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceLoadBalancerFeignClient.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceLoadBalancerFeignClient.java index d667f325e..fd4655e72 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceLoadBalancerFeignClient.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceLoadBalancerFeignClient.java @@ -2,7 +2,6 @@ package org.springframework.cloud.sleuth.instrument.web.client.feign; import java.io.IOException; import java.lang.invoke.MethodHandles; -import java.util.Objects; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; @@ -10,7 +9,6 @@ import org.springframework.beans.factory.BeanFactory; import org.springframework.cloud.netflix.feign.ribbon.CachingSpringLoadBalancerFactory; import org.springframework.cloud.netflix.feign.ribbon.LoadBalancerFeignClient; import org.springframework.cloud.netflix.ribbon.SpringClientFactory; -import org.springframework.cloud.sleuth.Span; import org.springframework.cloud.sleuth.Tracer; import feign.Client; @@ -40,23 +38,7 @@ class TraceLoadBalancerFeignClient extends LoadBalancerFeignClient { @Override public Response execute(Request request, Request.Options options) throws IOException { - Span currentSpan = tracer().getCurrentSpan(); - if (log.isDebugEnabled()) { - log.debug("Current span is " + currentSpan); - } - try { - return super.execute(request, options); - } catch (Exception e) { - if (Objects.equals(currentSpan, tracer().getCurrentSpan())) { - if (log.isDebugEnabled()) { - log.debug("Closing span " + currentSpan + " due to exception which is " - + "not handled by Feign. This can happen when the load balancer " - + "threw exception before Feign even managed to do sth about it"); - } - tracer().close(currentSpan); - } - throw e; - } + return super.execute(request, options); } private static Client wrap(Client delegate, BeanFactory beanFactory) { diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/exception/WebClientExceptionTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/exception/WebClientExceptionTests.java index 2d4fce19b..73d167bec 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/exception/WebClientExceptionTests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/exception/WebClientExceptionTests.java @@ -17,6 +17,7 @@ package org.springframework.cloud.sleuth.instrument.web.client.exception; import java.io.IOException; +import java.lang.invoke.MethodHandles; import java.util.Collections; import java.util.Map; @@ -24,12 +25,16 @@ import com.netflix.loadbalancer.BaseLoadBalancer; import com.netflix.loadbalancer.ILoadBalancer; import com.netflix.loadbalancer.Server; +import org.apache.commons.logging.Log; +import org.apache.commons.logging.LogFactory; import org.junit.After; import org.junit.Assert; import org.junit.Before; import org.junit.ClassRule; import org.junit.Rule; import org.junit.Test; +import org.junit.contrib.java.lang.system.SystemErrRule; +import org.junit.contrib.java.lang.system.SystemOutRule; import org.junit.runner.RunWith; import org.springframework.beans.factory.annotation.Autowired; import org.springframework.boot.autoconfigure.EnableAutoConfiguration; @@ -68,10 +73,16 @@ import static org.springframework.cloud.sleuth.assertions.SleuthAssertions.then; "spring.application.name=exceptionservice" }, randomPort = true) public class WebClientExceptionTests { + private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass()); + @ClassRule public static final SpringClassRule SCR = new SpringClassRule(); @Rule public final SpringMethodRule springMethodRule = new SpringMethodRule(); + @Rule + public final SystemErrRule systemErrRule = new SystemErrRule().enableLog(); + @Rule + public final SystemOutRule systemOutRule = new SystemOutRule().enableLog(); @Autowired TestFeignInterfaceWithException testFeignInterfaceWithException; @Autowired @LoadBalanced RestTemplate template; @@ -85,7 +96,6 @@ public class WebClientExceptionTests { @After public void close() { - ExceptionUtils.setFail(false); TestSpanContextHolder.removeCurrentSpan(); } @@ -95,6 +105,7 @@ public class WebClientExceptionTests { public void shouldCloseSpanUponException(ResponseEntityProvider provider) throws IOException { Span span = this.tracer.createSpan("new trace"); + log.info("Started new span " + span); try { provider.get(this); @@ -107,6 +118,9 @@ public class WebClientExceptionTests { then(ExceptionUtils.getLastException()).isNull(); then(this.tracer.getCurrentSpan()).isEqualTo(span); this.tracer.close(span); + then(ExceptionUtils.getLastException()).isNull(); + then(this.systemErrRule.getLog()).doesNotContain("Tried to detach trace span but it is not the current span"); + then(this.systemOutRule.getLog()).doesNotContain("Tried to detach trace span but it is not the current span"); } Object[] parametersForShouldCloseSpanUponException() { diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/FeignRetriesTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/FeignRetriesTests.java index 05365dab8..daaf6fba4 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/FeignRetriesTests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/FeignRetriesTests.java @@ -46,7 +46,7 @@ import org.springframework.cloud.sleuth.util.ExceptionUtils; import feign.Client; import feign.Feign; import feign.FeignException; -import feign.RequestInterceptor; +import feign.Request; import feign.RequestLine; import feign.Response; import okhttp3.mockwebserver.MockWebServer; @@ -68,8 +68,6 @@ public class FeignRetriesTests { ArrayListSpanAccumulator spanAccumulator = new ArrayListSpanAccumulator(); Tracer tracer = new DefaultTracer(new AlwaysSampler(), new Random(), new DefaultSpanNamer(), new NoOpSpanLogger(), this.spanAccumulator); - FeignRequestTemplateInjector injector = new FeignRequestTemplateInjector(); - TraceFeignRequestInterceptor interceptor = new TraceFeignRequestInterceptor(tracer, injector); @Before @After @@ -91,7 +89,6 @@ public class FeignRetriesTests { TestInterface api = Feign.builder() .client(new TraceFeignClient(beanFactory, client)) - .requestInterceptor(interceptor) .target(TestInterface.class, url); try { @@ -118,14 +115,15 @@ public class FeignRetriesTests { "OK", Charset.defaultCharset()); } }; - RequestInterceptor requestInterceptor = template -> { - atomicInteger.incrementAndGet(); - interceptor.apply(template); - }; TestInterface api = Feign.builder() - .client(new TraceFeignClient(beanFactory, client)) - .requestInterceptor(requestInterceptor) + .client(new TraceFeignClient(beanFactory, client) { + @Override public Response execute(Request request, + Request.Options options) throws IOException { + atomicInteger.incrementAndGet(); + return super.execute(request, options); + } + }) .target(TestInterface.class, url); then(api.decodedPost()).isEqualTo("OK"); diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClientTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClientTests.java index ba6905f22..1477bd2ce 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClientTests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClientTests.java @@ -74,18 +74,18 @@ public class TraceFeignClientTests { @Test public void should_log_cr_when_response_successful() throws IOException { - this.tracer.createSpan("foo"); + Span span = this.tracer.createSpan("foo"); Response response = this.traceFeignClient.execute( Request.create("GET", "http://foo", new HashMap<>(), "".getBytes(), Charset.defaultCharset()), new Request.Options()); - then(this.tracer.getCurrentSpan()).isNull(); + then(this.tracer.getCurrentSpan()).isEqualTo(span); then(this.spanAccumulator.getSpans().get(0)).hasLoggedAnEvent(Span.CLIENT_RECV); } @Test public void should_log_error_when_exception_thrown() throws IOException { - this.tracer.createSpan("foo"); + Span span = this.tracer.createSpan("foo"); BDDMockito.given(this.client.execute(BDDMockito.any(), BDDMockito.any())) .willThrow(new RuntimeException("exception has occurred")); @@ -96,7 +96,7 @@ public class TraceFeignClientTests { SleuthAssertions.fail("Exception should have been thrown"); } catch (Exception e) {} - then(this.tracer.getCurrentSpan()).isNull(); + then(this.tracer.getCurrentSpan()).isEqualTo(span); then(this.spanAccumulator.getSpans().get(0)) .hasNotLoggedAnEvent(Span.CLIENT_RECV) .hasATag("error", "exception has occurred"); diff --git a/spring-cloud-sleuth-stream/src/main/java/org/springframework/cloud/sleuth/stream/StreamSpanReporter.java b/spring-cloud-sleuth-stream/src/main/java/org/springframework/cloud/sleuth/stream/StreamSpanReporter.java index 575f06515..935b789be 100644 --- a/spring-cloud-sleuth-stream/src/main/java/org/springframework/cloud/sleuth/stream/StreamSpanReporter.java +++ b/spring-cloud-sleuth-stream/src/main/java/org/springframework/cloud/sleuth/stream/StreamSpanReporter.java @@ -16,12 +16,15 @@ package org.springframework.cloud.sleuth.stream; +import java.lang.invoke.MethodHandles; import java.util.Iterator; import java.util.LinkedList; import java.util.List; import java.util.concurrent.BlockingQueue; import java.util.concurrent.LinkedBlockingQueue; +import org.apache.commons.logging.Log; +import org.apache.commons.logging.LogFactory; import org.springframework.cloud.sleuth.Span; import org.springframework.cloud.sleuth.SpanReporter; import org.springframework.cloud.sleuth.metric.SpanMetricReporter; @@ -38,6 +41,8 @@ import org.springframework.integration.annotation.Poller; @MessageEndpoint public class StreamSpanReporter implements SpanReporter { + private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass()); + /** * Bean name for the * {@link org.springframework.integration.scheduling.PollerMetadata @@ -79,6 +84,10 @@ public class StreamSpanReporter implements SpanReporter { public void report(Span span) { if (span.isExportable()) { this.queue.add(span); + } else { + if (log.isDebugEnabled()) { + log.debug("The span " + span + " will not be sent to Zipkin due to sampling"); + } } } } 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 636b88a6b..07815baab 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 @@ -204,6 +204,10 @@ public class ZipkinSpanListener implements SpanReporter { public void report(Span span) { if (span.isExportable()) { this.reporter.report(convert(span)); + } else { + if (log.isDebugEnabled()) { + log.debug("The span " + span + " will not be sent to Zipkin due to sampling"); + } } } }