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

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;
+	}
 }

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")

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();

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