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

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

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

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.*$