From 10a169ed26c0419706ad8c2b2ffc72f141ccab26 Mon Sep 17 00:00:00 2001 From: Marcin Grzejszczak Date: Thu, 8 Sep 2016 15:08:01 +0200 Subject: [PATCH] TraceLoadBalancerFeignClient not closing span when TLBFC is throwing an exception the span wasn't closed. Throwing exception can occurr when IOExcepiton is thrown. Then the span wouldn't be closed and the whole series of problems occur. fixes #393 --- .../feign/TraceLoadBalancerFeignClient.java | 46 ++++++++++++++++++- .../WebClientDiscoveryExceptionTests.java | 10 ++-- .../feign/issues/issue393/Issue393Tests.java | 24 +--------- .../src/test/resources/application.yml | 3 ++ 4 files changed, 55 insertions(+), 28 deletions(-) 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 ec4ab9129..d667f325e 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 @@ -1,11 +1,21 @@ 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; 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; +import feign.Request; +import feign.Response; /** * We need to wrap the {@link LoadBalancerFeignClient} into a trace representation @@ -16,13 +26,47 @@ import feign.Client; */ class TraceLoadBalancerFeignClient extends LoadBalancerFeignClient { - public TraceLoadBalancerFeignClient(Client delegate, + private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass()); + + private final BeanFactory beanFactory; + private Tracer tracer; + + TraceLoadBalancerFeignClient(Client delegate, CachingSpringLoadBalancerFactory lbClientFactory, SpringClientFactory clientFactory, BeanFactory beanFactory) { super(wrap(delegate, beanFactory), lbClientFactory, clientFactory); + this.beanFactory = beanFactory; + } + + @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; + } } private static Client wrap(Client delegate, BeanFactory beanFactory) { return (Client) new TraceFeignObjectWrapper(beanFactory).wrap(delegate); } + + private Tracer tracer() { + if (this.tracer == null) { + this.tracer = this.beanFactory.getBean(Tracer.class); + } + return this.tracer; + } } diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/discoveryexception/WebClientDiscoveryExceptionTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/discoveryexception/WebClientDiscoveryExceptionTests.java index 1bf42d1a3..eeeea91c6 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/discoveryexception/WebClientDiscoveryExceptionTests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/discoveryexception/WebClientDiscoveryExceptionTests.java @@ -30,13 +30,13 @@ import org.springframework.boot.test.SpringApplicationConfiguration; import org.springframework.boot.test.WebIntegrationTest; import org.springframework.cloud.client.discovery.EnableDiscoveryClient; import org.springframework.cloud.client.loadbalancer.LoadBalanced; +import org.springframework.cloud.netflix.eureka.EurekaClientAutoConfiguration; import org.springframework.cloud.netflix.feign.EnableFeignClients; import org.springframework.cloud.netflix.feign.FeignClient; import org.springframework.cloud.netflix.ribbon.RibbonClient; import org.springframework.cloud.sleuth.Sampler; import org.springframework.cloud.sleuth.Span; import org.springframework.cloud.sleuth.Tracer; -import org.springframework.cloud.sleuth.assertions.SleuthAssertions; import org.springframework.cloud.sleuth.sampler.AlwaysSampler; import org.springframework.cloud.sleuth.trace.TestSpanContextHolder; import org.springframework.cloud.sleuth.util.ExceptionUtils; @@ -77,7 +77,7 @@ public class WebClientDiscoveryExceptionTests { // issue #240 private void shouldCloseSpanUponException(ResponseEntityProvider provider) - throws IOException { + throws IOException, InterruptedException { Span span = this.tracer.createSpan("new trace"); try { @@ -89,8 +89,10 @@ public class WebClientDiscoveryExceptionTests { assertThat(ExceptionUtils.getLastException()).isNull(); - SleuthAssertions.then(this.tracer.getCurrentSpan()).isEqualTo(span); + then(this.tracer.getCurrentSpan()).isEqualTo(span); this.tracer.close(span); + // hystrix commands should finish at this point + Thread.sleep(200); then(ExceptionUtils.getLastException()).isNull(); } @@ -114,7 +116,7 @@ public class WebClientDiscoveryExceptionTests { } @Configuration - @EnableAutoConfiguration + @EnableAutoConfiguration(exclude = EurekaClientAutoConfiguration.class) @EnableDiscoveryClient @EnableFeignClients @RibbonClient("exceptionservice") diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/issues/issue393/Issue393Tests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/issues/issue393/Issue393Tests.java index ac03cb6aa..10278508c 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/issues/issue393/Issue393Tests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/issues/issue393/Issue393Tests.java @@ -16,18 +16,8 @@ package org.springframework.cloud.sleuth.instrument.web.client.feign.issues.issue393; -import java.util.Date; -import java.util.Map; -import java.util.concurrent.ConcurrentHashMap; -import java.util.concurrent.ExecutionException; - -import com.fasterxml.jackson.annotation.JsonInclude; -import com.fasterxml.jackson.databind.annotation.JsonDeserialize; -import com.fasterxml.jackson.databind.annotation.JsonPOJOBuilder; - import org.junit.After; import org.junit.Before; -import org.junit.BeforeClass; import org.junit.Test; import org.junit.runner.RunWith; import org.springframework.beans.factory.annotation.Autowired; @@ -38,32 +28,20 @@ import org.springframework.cloud.client.discovery.EnableDiscoveryClient; import org.springframework.cloud.netflix.feign.EnableFeignClients; import org.springframework.cloud.netflix.feign.FeignClient; import org.springframework.cloud.sleuth.Tracer; -import org.springframework.cloud.sleuth.assertions.SleuthAssertions; import org.springframework.cloud.sleuth.sampler.AlwaysSampler; import org.springframework.cloud.sleuth.trace.TestSpanContextHolder; import org.springframework.cloud.sleuth.util.ExceptionUtils; import org.springframework.context.annotation.Bean; import org.springframework.context.annotation.Configuration; -import org.springframework.http.HttpStatus; import org.springframework.http.ResponseEntity; import org.springframework.test.context.TestPropertySource; import org.springframework.test.context.junit4.SpringJUnit4ClassRunner; import org.springframework.web.bind.annotation.PathVariable; import org.springframework.web.bind.annotation.RequestMapping; import org.springframework.web.bind.annotation.RequestMethod; -import org.springframework.web.bind.annotation.ResponseStatus; import org.springframework.web.bind.annotation.RestController; import org.springframework.web.client.RestTemplate; -import feign.Logger; -import feign.Response; -import feign.RetryableException; -import feign.Retryer; -import feign.codec.ErrorDecoder; - -import static org.assertj.core.api.Assertions.fail; -import static org.assertj.core.api.Assertions.registerCustomDateFormat; -import static org.assertj.core.api.Assertions.registerFormatterForType; import static org.assertj.core.api.BDDAssertions.then; /** @@ -73,7 +51,7 @@ import static org.assertj.core.api.BDDAssertions.then; @SpringApplicationConfiguration(Application.class) @WebIntegrationTest @TestPropertySource(properties = {"spring.application.name=demo-feign-uri", - "server.port=9978"}) + "server.port=9978", "eureka.client.enabled=true", "ribbon.eureka.enabled=true"}) public class Issue393Tests { RestTemplate template = new RestTemplate(); diff --git a/spring-cloud-sleuth-core/src/test/resources/application.yml b/spring-cloud-sleuth-core/src/test/resources/application.yml index d081e7e83..5b9e8f669 100644 --- a/spring-cloud-sleuth-core/src/test/resources/application.yml +++ b/spring-cloud-sleuth-core/src/test/resources/application.yml @@ -9,6 +9,9 @@ exceptionService.ribbon: ConnectTimeout: 1 ReadTimeout: 1 +eureka.client.enabled: false +ribbon.eureka.enabled: false + spring.sleuth.scheduled.skipPattern: "^org.*TestBeanWithScheduledMethodToBeIgnored$" # comma separated list of matchers spring.sleuth.rxjava.schedulers.ignoredthreads: HystixMetricPoller,^MyCustomThread.*$,^RxComputation.*$ \ No newline at end of file