From a9b4cbcfe6e721823a0058afdcbf61a182b23f42 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 | 14 ++++-- .../feign/issues/issue393/Issue393Tests.java | 2 +- .../src/test/resources/application.yml | 1 + 4 files changed, 57 insertions(+), 6 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 fde2db7ed..7d3be61d9 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 @@ -22,20 +22,22 @@ import java.util.Map; import org.assertj.core.api.Assertions; import org.junit.After; import org.junit.Before; +import org.junit.Rule; 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.rule.OutputCapture; 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; @@ -63,6 +65,7 @@ public class WebClientDiscoveryExceptionTests { @Autowired TestFeignInterfaceWithException testFeignInterfaceWithException; @Autowired @LoadBalanced RestTemplate template; @Autowired Tracer tracer; + @Rule public OutputCapture outputCapture = new OutputCapture(); @Before public void open() { @@ -77,7 +80,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,9 +92,12 @@ public class WebClientDiscoveryExceptionTests { assertThat(ExceptionUtils.getLastException()).isNull(); - SleuthAssertions.then(this.tracer.getCurrentSpan()).isEqualTo(span); + then(this.tracer.getCurrentSpan()).isEqualTo(span); this.tracer.close(span); then(ExceptionUtils.getLastException()).isNull(); + // hystrix commands should finish at this point + Thread.sleep(200); + then(this.outputCapture.toString()).doesNotContain("Tried to detach trace span but it is not the current span"); } @Test @@ -114,7 +120,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 2f513f4dc..b221d9d6d 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 @@ -49,7 +49,7 @@ import static org.assertj.core.api.BDDAssertions.then; @RunWith(SpringJUnit4ClassRunner.class) @SpringBootTest(classes = Application.class, webEnvironment = SpringBootTest.WebEnvironment.DEFINED_PORT) @TestPropertySource(properties = {"spring.application.name=demo-feign-uri", - "server.port=9978", "eureka.client.enabled=true"}) + "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 503ad9c80..5b9e8f669 100644 --- a/spring-cloud-sleuth-core/src/test/resources/application.yml +++ b/spring-cloud-sleuth-core/src/test/resources/application.yml @@ -10,6 +10,7 @@ exceptionService.ribbon: ReadTimeout: 1 eureka.client.enabled: false +ribbon.eureka.enabled: false spring.sleuth.scheduled.skipPattern: "^org.*TestBeanWithScheduledMethodToBeIgnored$" # comma separated list of matchers