Fixed the issues with Zuul exception handling (#300)

TraceFilter no longer is a OncePerRequestFilter
TraceFilter processes the request that is executed upon ERROR dispatch (the logs will be present there)
Altered the logic in TraceFilter that an already processed request will not be detached (which resulted in an exception)
Added some debugging to instrumentation
Added assertion over a list of spans
Bumped up SC-Netflix to 1.1.2.BUILD-SNAPSHOT
Added Zuul integration tests
Added Http keys injection to Zuul client call

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/Span.java

@@ -27,13 +27,13 @@ import java.util.List;
 import java.util.Map;
 import java.util.Set;
 
-import org.springframework.util.Assert;
-import org.springframework.util.StringUtils;
-
 import com.fasterxml.jackson.annotation.JsonAutoDetect;
 import com.fasterxml.jackson.annotation.JsonIgnore;
 import com.fasterxml.jackson.annotation.JsonInclude;
 
+import org.springframework.util.Assert;
+import org.springframework.util.StringUtils;
+
 /**
  * Class for gathering and reporting statistics about a block of execution.
  * <p>
@@ -377,7 +377,11 @@ public class Span {
 	@Override
 	public String toString() {
 		return "[Trace: " + idToHex(this.traceId) + ", Span: " + idToHex(this.spanId)
-				+ ", exportable=" + this.exportable + "]";
+				+ ", Parent: " + getParentIdIfPresent() + ", exportable=" + this.exportable + "]";
+	}
+
+	private String getParentIdIfPresent() {
+		return this.getParents().isEmpty() ? "null" : idToHex(this.getParents().get(0));
 	}
 
 	@Override

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/rxjava/SleuthRxJavaSchedulersHook.java

@@ -56,12 +56,14 @@ class SleuthRxJavaSchedulersHook extends RxJavaSchedulersHook {
 
 	private void logCurrentStateOfRxJavaPlugins(RxJavaErrorHandler errorHandler,
 		RxJavaObservableExecutionHook observableExecutionHook) {
-		log.debug("Current RxJava plugins configuration is ["
-			+ "schedulersHook [" + this.delegate + "],"
-			+ "errorHandler [" + errorHandler + "],"
-			+ "observableExecutionHook [" + observableExecutionHook + "],"
-			+ "]");
-		log.debug("Registering Sleuth RxJava Schedulers Hook.");
+		if (log.isDebugEnabled()) {
+			log.debug("Current RxJava plugins configuration is ["
+					+ "schedulersHook [" + this.delegate + "],"
+					+ "errorHandler [" + errorHandler + "],"
+					+ "observableExecutionHook [" + observableExecutionHook + "],"
+					+ "]");
+			log.debug("Registering Sleuth RxJava Schedulers Hook.");
+		}
 	}
 
 	@Override
@@ -102,9 +104,11 @@ class SleuthRxJavaSchedulersHook extends RxJavaSchedulersHook {
 			for (String threadToIgnore : this.threadsToIgnore) {
 				String threadName = Thread.currentThread().getName();
 				if (threadName.matches(threadToIgnore)) {
-					log.trace(String.format(
-							"Thread with name [%s] matches the regex [%s]. A span will not be created for this Thread.",
-							threadName, threadToIgnore));
+					if (log.isTraceEnabled()) {
+						log.trace(String.format(
+								"Thread with name [%s] matches the regex [%s]. A span will not be created for this Thread.",
+								threadName, threadToIgnore));
+					}
 					this.actual.call();
 					return;
 				}

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/HttpTraceKeysInjector.java

@@ -1,5 +1,6 @@
 package org.springframework.cloud.sleuth.instrument.web;
 
+import java.net.URI;
 import java.util.Collection;
 import java.util.Map;
 
@@ -45,6 +46,13 @@ public class HttpTraceKeysInjector {
 		tagSpan(span, this.traceKeys.getHttp().getMethod(), method);
 	}
 
+	/**
+	 * Adds tags from the HTTP request to the given Span
+	 */
+	public void addRequestTags(Span span, URI uri, String method) {
+		addRequestTags(span, uri.toString(), uri.getHost(), uri.getPath(), method);
+	}
+
 	/**
 	 * Adds tags from the HTTP request together with headers to the current Span
 	 */

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceFilter.java

@@ -17,14 +17,19 @@ package org.springframework.cloud.sleuth.instrument.web;
 
 import javax.servlet.FilterChain;
 import javax.servlet.ServletException;
+import javax.servlet.ServletRequest;
+import javax.servlet.ServletResponse;
 import javax.servlet.http.HttpServletRequest;
 import javax.servlet.http.HttpServletResponse;
 import java.io.IOException;
+import java.lang.invoke.MethodHandles;
 import java.util.ArrayList;
 import java.util.Collections;
 import java.util.Enumeration;
 import java.util.regex.Pattern;
 
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
 import org.springframework.cloud.sleuth.Span;
 import org.springframework.cloud.sleuth.SpanExtractor;
 import org.springframework.cloud.sleuth.SpanInjector;
@@ -36,7 +41,8 @@ import org.springframework.core.Ordered;
 import org.springframework.core.annotation.Order;
 import org.springframework.http.HttpStatus;
 import org.springframework.util.StringUtils;
-import org.springframework.web.filter.OncePerRequestFilter;
+import org.springframework.web.context.request.async.WebAsyncUtils;
+import org.springframework.web.filter.GenericFilterBean;
 import org.springframework.web.util.UrlPathHelper;
 
 import static org.springframework.util.StringUtils.hasText;
@@ -63,13 +69,18 @@ import static org.springframework.util.StringUtils.hasText;
  * @see TraceWebAutoConfiguration#traceFilter
  */
 @Order(Ordered.HIGHEST_PRECEDENCE + 5)
-public class TraceFilter extends OncePerRequestFilter {
+public class TraceFilter extends GenericFilterBean {
+
+	private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass());
 
 	private static final String HTTP_COMPONENT = "http";
 
 	protected static final String TRACE_REQUEST_ATTR = TraceFilter.class.getName()
 			+ ".TRACE";
 
+	protected static final String TRACE_ERROR_HANDLED_REQUEST_ATTR = TraceFilter.class.getName()
+			+ ".ERROR_HANDLED";
+
 	public static final String DEFAULT_SKIP_PATTERN =
 			"/api-docs.*|/autoconfig|/configprops|/dump|/health|/info|/metrics.*|/mappings|/trace|/swagger.*|.*\\.png|.*\\.css|.*\\.js|.*\\.html|/favicon.ico|/hystrix.stream";
 
@@ -105,22 +116,36 @@ public class TraceFilter extends OncePerRequestFilter {
 	}
 
 	@Override
-	protected void doFilterInternal(HttpServletRequest request,
-			HttpServletResponse response, FilterChain filterChain)
-			throws ServletException, IOException {
+	public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse,
+			FilterChain filterChain) throws IOException, ServletException {
+		if (!(servletRequest instanceof HttpServletRequest) || !(servletResponse instanceof HttpServletResponse)) {
+			throw new ServletException("Filter just supports HTTP requests");
+		}
+		HttpServletRequest request = (HttpServletRequest) servletRequest;
+		HttpServletResponse response = (HttpServletResponse) servletResponse;
 		String uri = this.urlPathHelper.getPathWithinApplication(request);
 		boolean skip = this.skipPattern.matcher(uri).matches()
 				|| Span.SPAN_NOT_SAMPLED.equals(ServletUtils.getHeader(request, response, Span.SAMPLED_NAME));
 		Span spanFromRequest = getSpanFromAttribute(request);
 		if (spanFromRequest != null) {
 			this.tracer.continueSpan(spanFromRequest);
+			if (log.isTraceEnabled()) {
+				log.trace("There has already been a span in the request " + spanFromRequest + "");
+			}
+		}
+		if (log.isTraceEnabled()) {
+			log.trace("Received a request to uri [" + uri + "] that matches the skip pattern [" + skip + "]");
 		}
 		// in case of a response with exception status a exception controller will close the span
 		if (!httpStatusSuccessful(response) && isSpanContinued(request)) {
-			// it means that the span was already detached once and we're processing an error
+			if (log.isTraceEnabled()) {
+				log.trace(
+						"The span was already detached once and we're processing an error");
+			}
 			try {
 				filterChain.doFilter(request, response);
 			} finally {
+				request.setAttribute(TRACE_ERROR_HANDLED_REQUEST_ATTR, true);
 				this.tracer.close(spanFromRequest);
 			}
 			return;
@@ -141,6 +166,9 @@ public class TraceFilter extends OncePerRequestFilter {
 		}
 		finally {
 			if (isAsyncStarted(request) || request.isAsyncStarted()) {
+				if (log.isTraceEnabled()) {
+					log.trace("Detaching the span " + spanFromRequest + " since the request is asynchronous");
+				}
 				this.tracer.detach(spanFromRequest);
 				// TODO: how to deal with response annotations and async?
 				return;
@@ -151,6 +179,9 @@ public class TraceFilter extends OncePerRequestFilter {
 				if (spanFromRequest.hasSavedSpan()) {
 					Span parent =  spanFromRequest.getSavedSpan();
 					if (parent.isRemote()) {
+						if (log.isTraceEnabled()) {
+							log.trace("Sending the parent span " + parent + " to Zipkin");
+						}
 						parent.logEvent(Span.SERVER_SEND);
 						parent.stop();
 						this.spanReporter.report(parent);
@@ -160,8 +191,19 @@ public class TraceFilter extends OncePerRequestFilter {
 				}
 				// in case of a response with exception status will close the span when exception dispatch is handled
 				if (httpStatusSuccessful(response)) {
+					if (log.isTraceEnabled()) {
+						log.trace("Closing the span " + spanFromRequest + " since the response was successful");
+					}
 					this.tracer.close(spanFromRequest);
+				} else if (errorAlreadyHandled(request)) {
+					if (log.isTraceEnabled()) {
+						log.trace(
+								"Won't detach the span since error has already been handled");
+					}
 				} else {
+					if (log.isTraceEnabled()) {
+						log.trace("Detaching the span " + spanFromRequest + " since the response was unsuccessful");
+					}
 					this.tracer.detach(spanFromRequest);
 				}
 			}
@@ -177,6 +219,11 @@ public class TraceFilter extends OncePerRequestFilter {
 		return (Span) request.getAttribute(TRACE_REQUEST_ATTR);
 	}
 
+	private boolean errorAlreadyHandled(HttpServletRequest request) {
+		return Boolean.valueOf(
+				String.valueOf(request.getAttribute(TRACE_ERROR_HANDLED_REQUEST_ATTR)));
+	}
+
 	private boolean isSpanContinued(HttpServletRequest request) {
 		return getSpanFromAttribute(request) != null;
 	}
@@ -193,16 +240,28 @@ public class TraceFilter extends OncePerRequestFilter {
 	private Span createSpan(HttpServletRequest request,
 			boolean skip, Span spanFromRequest, String name) {
 		if (spanFromRequest != null) {
+			if (log.isTraceEnabled()) {
+				log.trace("Span has already been created - continuing with the previous one");
+			}
 			return spanFromRequest;
 		}
 		Span parent = this.spanExtractor.joinTrace(request);
 		if (parent != null) {
+			if (log.isTraceEnabled()) {
+				log.trace("Found a parent span " + parent + " in the request");
+			}
 			addRequestTagsForParentSpan(request, parent);
 			spanFromRequest = this.tracer.createSpan(name, parent);
+			if (log.isTraceEnabled()) {
+				log.trace("Started a new span " + spanFromRequest + " with parent " + parent);
+			}
 			if (parent.isRemote()) {
 				parent.logEvent(Span.SERVER_RECV);
 			}
 			request.setAttribute(TRACE_REQUEST_ATTR, spanFromRequest);
+			if (log.isTraceEnabled()) {
+				log.trace("Parent span is " + parent + "");
+			}
 		}
 		else {
 			if (skip) {
@@ -213,6 +272,7 @@ public class TraceFilter extends OncePerRequestFilter {
 			}
 			spanFromRequest.logEvent(Span.SERVER_RECV);
 			request.setAttribute(TRACE_REQUEST_ATTR, spanFromRequest);
+			log.trace("No parent span present - creating a new span");
 		}
 		return spanFromRequest;
 	}
@@ -256,9 +316,8 @@ public class TraceFilter extends OncePerRequestFilter {
 		}
 	}
 
-	@Override
-	protected boolean shouldNotFilterAsyncDispatch() {
-		return false;
+	protected boolean isAsyncStarted(HttpServletRequest request) {
+		return WebAsyncUtils.getAsyncManager(request).isConcurrentHandlingStarted();
 	}
 
 	private String getFullUrl(HttpServletRequest request) {
@@ -266,14 +325,8 @@ public class TraceFilter extends OncePerRequestFilter {
 		String queryString = request.getQueryString();
 		if (queryString == null) {
 			return requestURI.toString();
-		}
-		else {
+		} else {
 			return requestURI.append('?').append(queryString).toString();
 		}
 	}
-
-	@Override
-	protected boolean shouldNotFilterErrorDispatch() {
-		return false;
-	}
 }

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/AbstractTraceHttpRequestInterceptor.java

@@ -16,8 +16,11 @@
 
 package org.springframework.cloud.sleuth.instrument.web.client;
 
+import java.lang.invoke.MethodHandles;
 import java.net.URI;
 
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
 import org.springframework.cloud.sleuth.Span;
 import org.springframework.cloud.sleuth.SpanInjector;
 import org.springframework.cloud.sleuth.Tracer;
@@ -32,6 +35,8 @@ import org.springframework.http.HttpRequest;
  */
 abstract class AbstractTraceHttpRequestInterceptor {
 
+	protected static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass());
+
 	protected final Tracer tracer;
 	protected final SpanInjector<HttpRequest> spanInjector;
 	protected final HttpTraceKeysInjector keysInjector;
@@ -54,6 +59,9 @@ abstract class AbstractTraceHttpRequestInterceptor {
 		this.spanInjector.inject(newSpan, request);
 		addRequestTags(request);
 		newSpan.logEvent(Span.CLIENT_SEND);
+		if (log.isTraceEnabled()) {
+			log.trace("Starting new client span [" + newSpan + "]");
+		}
 	}
 
 	private String uriScheme(URI uri) {

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/TraceRestTemplateInterceptor.java

@@ -56,6 +56,9 @@ public class TraceRestTemplateInterceptor extends AbstractTraceHttpRequestInterc
 		try {
 			return new TraceHttpResponse(this, execution.execute(request, body));
 		} catch (Exception e) {
+			if (log.isTraceEnabled()) {
+				log.trace("Exception occurred while trying to execute the request", e);
+			}
 			this.tracer.close(currentSpan());
 			throw e;
 		}

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/zuul/TracePostZuulFilter.java

@@ -16,12 +16,16 @@
 
 package org.springframework.cloud.sleuth.instrument.zuul;
 
-import org.springframework.cloud.sleuth.Span;
-import org.springframework.cloud.sleuth.Tracer;
+import java.lang.invoke.MethodHandles;
 
 import com.netflix.zuul.ZuulFilter;
 
-/**
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
+import org.springframework.cloud.sleuth.Span;
+import org.springframework.cloud.sleuth.Tracer;
+
+/**8
  * A post request {@link ZuulFilter} that publishes an event upon start of the filtering
  *
  * @author Dave Syer
@@ -29,6 +33,8 @@ import com.netflix.zuul.ZuulFilter;
  */
 public class TracePostZuulFilter extends ZuulFilter {
 
+	private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass());
+
 	private final Tracer tracer;
 
 	public TracePostZuulFilter(Tracer tracer) {
@@ -44,6 +50,9 @@ public class TracePostZuulFilter extends ZuulFilter {
 	public Object run() {
 		// TODO: the client sent event should come from the client not the filter!
 		getCurrentSpan().logEvent(Span.CLIENT_RECV);
+		if (log.isTraceEnabled()) {
+			log.trace("Closing current client span " + getCurrentSpan() + "");
+		}
 		this.tracer.close(getCurrentSpan());
 		return null;
 	}

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/zuul/TracePreZuulFilter.java

@@ -16,15 +16,19 @@
 
 package org.springframework.cloud.sleuth.instrument.zuul;
 
-import org.springframework.cloud.sleuth.Span;
-import org.springframework.cloud.sleuth.SpanInjector;
-import org.springframework.cloud.sleuth.Tracer;
+import java.lang.invoke.MethodHandles;
 
 import com.netflix.zuul.ExecutionStatus;
 import com.netflix.zuul.ZuulFilter;
 import com.netflix.zuul.ZuulFilterResult;
 import com.netflix.zuul.context.RequestContext;
 
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
+import org.springframework.cloud.sleuth.Span;
+import org.springframework.cloud.sleuth.SpanInjector;
+import org.springframework.cloud.sleuth.Tracer;
+
 /**
  * A pre request {@link ZuulFilter} that sets tracing related headers on the request
  * from the current span. We're doing so to ensure tracing propagates to the next hop.
@@ -34,6 +38,8 @@ import com.netflix.zuul.context.RequestContext;
  */
 public class TracePreZuulFilter extends ZuulFilter {
 
+	private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass());
+
 	private static final String ZUUL_COMPONENT = "zuul";
 
 	private final Tracer tracer;
@@ -59,11 +65,24 @@ public class TracePreZuulFilter extends ZuulFilter {
 	public ZuulFilterResult runFilter() {
 		RequestContext ctx = RequestContext.getCurrentContext();
 		Span span = getCurrentSpan();
+		if (log.isTraceEnabled()) {
+			log.trace("Current span is " + span + "");
+		}
 		Span newSpan = this.tracer.createSpan(span.getName(), span);
 		newSpan.tag(Span.SPAN_LOCAL_COMPONENT_TAG_NAME, ZUUL_COMPONENT);
 		this.spanInjector.inject(newSpan, ctx);
+		if (log.isTraceEnabled()) {
+			log.trace("New Zuul Span is " + newSpan + "");
+		}
 		ZuulFilterResult result = super.runFilter();
+		if (log.isTraceEnabled()) {
+			log.trace("Result of Zuul filter is [" + result.getStatus() + "]");
+		}
 		if (ExecutionStatus.SUCCESS != result.getStatus()) {
+			if (log.isTraceEnabled()) {
+				log.trace("The result of Zuul filter execution was not successful thus "
+						+ "will close the current span " + newSpan);
+			}
 			this.tracer.close(newSpan);
 		}
 		return result;

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/zuul/TraceRestClientRibbonCommandFactory.java

@@ -19,6 +19,9 @@ package org.springframework.cloud.sleuth.instrument.zuul;
 import java.io.InputStream;
 import java.net.URISyntaxException;
 
+import com.netflix.client.http.HttpRequest;
+import com.netflix.niws.client.http.RestClient;
+
 import org.apache.commons.logging.Log;
 import org.apache.commons.logging.LogFactory;
 import org.springframework.cloud.netflix.ribbon.SpringClientFactory;
@@ -28,11 +31,9 @@ import org.springframework.cloud.netflix.zuul.filters.route.RibbonCommandContext
 import org.springframework.cloud.sleuth.Span;
 import org.springframework.cloud.sleuth.SpanInjector;
 import org.springframework.cloud.sleuth.Tracer;
+import org.springframework.cloud.sleuth.instrument.web.HttpTraceKeysInjector;
 import org.springframework.util.MultiValueMap;
 
-import com.netflix.client.http.HttpRequest;
-import com.netflix.niws.client.http.RestClient;
-
 /**
  * Propagates traces downstream via http headers that contain trace metadata.
  *
@@ -45,12 +46,15 @@ public class TraceRestClientRibbonCommandFactory extends RestClientRibbonCommand
 
 	private final Tracer tracer;
 	private final SpanInjector<HttpRequest.Builder> spanInjector;
+	private final HttpTraceKeysInjector httpTraceKeysInjector;
 
 	public TraceRestClientRibbonCommandFactory(SpringClientFactory clientFactory,
-			Tracer tracer, SpanInjector<HttpRequest.Builder> spanInjector) {
+			Tracer tracer, SpanInjector<HttpRequest.Builder> spanInjector,
+			HttpTraceKeysInjector httpTraceKeysInjector) {
 		super(clientFactory);
 		this.tracer = tracer;
 		this.spanInjector = spanInjector;
+		this.httpTraceKeysInjector = httpTraceKeysInjector;
 	}
 
 	@Override
@@ -62,7 +66,7 @@ public class TraceRestClientRibbonCommandFactory extends RestClientRibbonCommand
 			return new TraceRestClientRibbonCommand(context.getServiceId(), restClient,
 					getVerb(context.getVerb()), context.getUri(), context.getRetryable(),
 					context.getHeaders(), context.getParams(), context.getRequestEntity(),
-					this.tracer, this.spanInjector);
+					this.tracer, this.spanInjector, this.httpTraceKeysInjector);
 		}
 		catch (URISyntaxException e) {
 			log.error("Exception occurred while trying to create the TraceRestClientRibbonCommand", e);
@@ -74,25 +78,32 @@ public class TraceRestClientRibbonCommandFactory extends RestClientRibbonCommand
 
 		private final Tracer tracer;
 		private final SpanInjector<HttpRequest.Builder> spanInjector;
+		private final HttpTraceKeysInjector httpTraceKeysInjector;
 
 		@SuppressWarnings("deprecation")
 		public TraceRestClientRibbonCommand(String commandKey, RestClient restClient,
 				HttpRequest.Verb verb, String uri, Boolean retryable,
 				MultiValueMap<String, String> headers,
 				MultiValueMap<String, String> params, InputStream requestEntity,
-				Tracer tracer, SpanInjector<HttpRequest.Builder> spanInjector)
+				Tracer tracer, SpanInjector<HttpRequest.Builder> spanInjector,
+				HttpTraceKeysInjector httpTraceKeysInjector)
 						throws URISyntaxException {
 			super(commandKey, restClient, verb, uri, retryable, headers, params,
 					requestEntity);
 			this.tracer = tracer;
 			this.spanInjector = spanInjector;
+			this.httpTraceKeysInjector = httpTraceKeysInjector;
 		}
 
 		@Override
 		protected void customizeRequest(HttpRequest.Builder requestBuilder) {
 			Span span = getCurrentSpan();
 			this.spanInjector.inject(span, requestBuilder);
+			this.httpTraceKeysInjector.addRequestTags(span, getUri(), getVerb().verb());
 			span.logEvent(Span.CLIENT_SEND);
+			if (log.isTraceEnabled()) {
+				log.trace("Span is " + span);
+			}
 		}
 
 		private Span getCurrentSpan() {

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/zuul/TraceZuulAutoConfiguration.java

@@ -25,6 +25,7 @@ import org.springframework.cloud.netflix.ribbon.SpringClientFactory;
 import org.springframework.cloud.sleuth.SpanInjector;
 import org.springframework.cloud.sleuth.Tracer;
 import org.springframework.cloud.sleuth.autoconfig.TraceAutoConfiguration;
+import org.springframework.cloud.sleuth.instrument.web.HttpTraceKeysInjector;
 import org.springframework.context.annotation.Bean;
 import org.springframework.context.annotation.Configuration;
 
@@ -56,8 +57,9 @@ public class TraceZuulAutoConfiguration {
 
 	@Bean
 	public TraceRestClientRibbonCommandFactory traceRestClientRibbonCommandFactory(SpringClientFactory factory,
-			Tracer tracer, SpanInjector<HttpRequest.Builder> spanInjector) {
-		return new TraceRestClientRibbonCommandFactory(factory, tracer, spanInjector);
+			Tracer tracer, SpanInjector<HttpRequest.Builder> spanInjector, HttpTraceKeysInjector httpTraceKeysInjector) {
+		return new TraceRestClientRibbonCommandFactory(factory, tracer, spanInjector,
+				httpTraceKeysInjector);
 	}
 
 	@Bean

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/log/Slf4jSpanLogger.java

@@ -83,7 +83,9 @@ public class Slf4jSpanLogger implements SpanLogger {
 		if (span != null && this.nameSkipPattern.matcher(span.getName()).matches()) {
 			return;
 		}
-		this.log.trace(text, span);
+		if (this.log.isTraceEnabled()) {
+			this.log.trace(text, span);
+		}
 	}
 
 }

spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/SpanTests.java

@@ -19,11 +19,11 @@ package org.springframework.cloud.sleuth;
 import java.io.IOException;
 import java.util.Collections;
 
-import org.junit.Test;
-
 import com.fasterxml.jackson.core.JsonProcessingException;
 import com.fasterxml.jackson.databind.ObjectMapper;
 
+import org.junit.Test;
+
 import static org.assertj.core.api.BDDAssertions.then;
 
 /**
@@ -31,7 +31,7 @@ import static org.assertj.core.api.BDDAssertions.then;
  * @author Rob Winch
  * @author Spencer Gibb
  */
-public class SpanTest {
+public class SpanTests {
 
 	@Test
 	public void should_convert_long_to_hex_string() throws Exception {

spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/assertions/ListOfSpans.java

@@ -0,0 +1,32 @@
+/*
+ * 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.assertions;
+
+import java.util.List;
+
+import org.springframework.cloud.sleuth.Span;
+
+/**
+ * @author Marcin Grzejszczak
+ */
+public class ListOfSpans {
+
+	public final List<Span> spans;
+
+	public ListOfSpans(List<Span> spans) {
+		this.spans = spans;
+	}
+}

spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/assertions/ListOfSpansAssert.java

@@ -0,0 +1,78 @@
+/*
+ * 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.assertions;
+
+import java.util.ArrayList;
+import java.util.List;
+import java.util.stream.Collectors;
+
+import com.fasterxml.jackson.core.JsonProcessingException;
+import com.fasterxml.jackson.databind.ObjectMapper;
+
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
+import org.assertj.core.api.AbstractAssert;
+import org.assertj.core.api.Assertions;
+import org.springframework.cloud.sleuth.Span;
+
+public class ListOfSpansAssert extends AbstractAssert<ListOfSpansAssert, ListOfSpans> {
+
+	private static final Log log = LogFactory.getLog(ListOfSpansAssert.class);
+
+	private final ObjectMapper objectMapper = new ObjectMapper();
+
+	public ListOfSpansAssert(ListOfSpans actual) {
+		super(actual, ListOfSpansAssert.class);
+	}
+
+	public static ListOfSpansAssert then(ListOfSpans actual) {
+		return new ListOfSpansAssert(actual);
+	}
+
+	public ListOfSpansAssert thereIsOnlyOneServerAndClientSideSpanWhoseParentIdIsEqualTo(long traceId) {
+		isNotNull();
+		printSpans();
+		List<Span> spansWithParentSpanAsRootSpan = this.actual.spans.stream().filter(span -> span.getParents().contains(traceId)).collect(Collectors.toList());
+		Assertions.assertThat(spansWithParentSpanAsRootSpan).hasSize(2).extracting("spanId").containsOnly(spansWithParentSpanAsRootSpan.get(0).getSpanId());
+		return this;
+	}
+
+	public ListOfSpansAssert everyParentIdHasItsCorrespondingSpan() {
+		isNotNull();
+		printSpans();
+		List<Long> parentSpanIds = this.actual.spans.stream().flatMap(span -> span.getParents().stream())
+				.distinct().collect(Collectors.toList());
+		List<Long> spanIds = this.actual.spans.stream()
+				.map(Span::getSpanId).distinct()
+				.collect(Collectors.toList());
+		List<Long> difference = new ArrayList<>(parentSpanIds);
+		difference.removeAll(spanIds);
+		log.info("Difference between parent ids and span ids " +
+				difference.stream().map(span -> "id as long [" + span + "] and as hex [" + Span.idToHex(span) + "]").collect(Collectors.joining("\n")));
+		Assertions.assertThat(spanIds).containsAll(parentSpanIds);
+		return this;
+	}
+
+	private void printSpans() {
+		try {
+			log.info("Stored spans " + this.objectMapper.writeValueAsString(this.actual.spans));
+		}
+		catch (JsonProcessingException e) {
+		}
+	}
+
+}

spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/assertions/SleuthAssertions.java

@@ -13,4 +13,13 @@ public class SleuthAssertions extends BDDAssertions {
 		return new SpanAssert(actual);
 	}
 
+
+	public static ListOfSpansAssert then(ListOfSpans actual) {
+		return assertThat(actual);
+	}
+
+	public static ListOfSpansAssert assertThat(ListOfSpans actual) {
+		return new ListOfSpansAssert(actual);
+	}
+
 }

spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterTests.java

@@ -171,6 +171,39 @@ public class TraceFilterTests {
 				this.spanExtractor, this.spanInjector, this.httpTraceKeysInjector);
 		filter.doFilter(this.request, this.response, this.filterChain);
 
+		then(TestSpanContextHolder.getCurrentSpan()).isNull();
+		then(this.request.getAttribute(TraceFilter.TRACE_ERROR_HANDLED_REQUEST_ATTR)).isNull();
+	}
+
+	@Test
+	public void closesSpanInRequestAttrIfStatusCodeNotSuccessful() throws Exception {
+		Span span = this.tracer.createSpan("http:foo");
+		this.request.setAttribute(TraceFilter.TRACE_REQUEST_ATTR, span);
+		this.response.setStatus(404);
+		// It should have been removed from the thread local context so simulate that
+		TestSpanContextHolder.removeCurrentSpan();
+
+		TraceFilter filter = new TraceFilter(this.tracer, this.traceKeys, this.spanReporter,
+				this.spanExtractor, this.spanInjector, this.httpTraceKeysInjector);
+		filter.doFilter(this.request, this.response, this.filterChain);
+
+		then(TestSpanContextHolder.getCurrentSpan()).isNull();
+		then(this.request.getAttribute(TraceFilter.TRACE_ERROR_HANDLED_REQUEST_ATTR)).isNotNull();
+	}
+
+	@Test
+	public void doesntDetachASpanIfStatusCodeNotSuccessfulAndRequestWasProcessed() throws Exception {
+		Span span = this.tracer.createSpan("http:foo");
+		this.request.setAttribute(TraceFilter.TRACE_REQUEST_ATTR, span);
+		this.request.setAttribute(TraceFilter.TRACE_ERROR_HANDLED_REQUEST_ATTR, true);
+		this.response.setStatus(404);
+		// It should have been removed from the thread local context so simulate that
+		TestSpanContextHolder.removeCurrentSpan();
+
+		TraceFilter filter = new TraceFilter(this.tracer, this.traceKeys, this.spanReporter,
+				this.spanExtractor, this.spanInjector, this.httpTraceKeysInjector);
+		filter.doFilter(this.request, this.response, this.filterChain);
+
 		then(TestSpanContextHolder.getCurrentSpan()).isNull();
 	}
 

spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/WebClientTests.java

@@ -58,7 +58,6 @@ import org.springframework.context.annotation.Bean;
 import org.springframework.context.annotation.Configuration;
 import org.springframework.http.HttpHeaders;
 import org.springframework.http.ResponseEntity;
-import org.springframework.stereotype.Component;
 import org.springframework.test.context.junit4.rules.SpringClassRule;
 import org.springframework.test.context.junit4.rules.SpringMethodRule;
 import org.springframework.web.bind.annotation.RequestHeader;

spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/zuul/TraceRestClientRibbonCommandFactoryTest.java

@@ -16,10 +16,8 @@
 
 package org.springframework.cloud.sleuth.instrument.zuul;
 
-import static org.assertj.core.api.BDDAssertions.then;
-import static org.mockito.BDDMockito.given;
-import static org.mockito.Matchers.any;
-import static org.mockito.Matchers.anyString;
+import com.netflix.client.http.HttpRequest;
+import com.netflix.niws.client.http.RestClient;
 
 import org.junit.Before;
 import org.junit.Test;
@@ -32,9 +30,12 @@ import org.springframework.cloud.netflix.zuul.filters.route.RibbonCommandContext
 import org.springframework.cloud.sleuth.Span;
 import org.springframework.cloud.sleuth.SpanInjector;
 import org.springframework.cloud.sleuth.Tracer;
+import org.springframework.cloud.sleuth.instrument.web.HttpTraceKeysInjector;
 
-import com.netflix.client.http.HttpRequest;
-import com.netflix.niws.client.http.RestClient;
+import static org.assertj.core.api.BDDAssertions.then;
+import static org.mockito.BDDMockito.given;
+import static org.mockito.Matchers.any;
+import static org.mockito.Matchers.anyString;
 
 /**
  * @author Marcin Grzejszczak
@@ -42,18 +43,18 @@ import com.netflix.niws.client.http.RestClient;
 @RunWith(MockitoJUnitRunner.class)
 public class TraceRestClientRibbonCommandFactoryTest {
 
-	@Mock
-	Tracer tracer;
-	@Mock
-	SpringClientFactory springClientFactory;
+	@Mock Tracer tracer;
+	@Mock SpringClientFactory springClientFactory;
 	SpanInjector<HttpRequest.Builder> spanInjector = new RequestBuilderContextInjector();
+	@Mock HttpTraceKeysInjector httpTraceKeysInjector;
 	TraceRestClientRibbonCommandFactory traceRestClientRibbonCommandFactory;
 
 	@Before
 	@SuppressWarnings({ "deprecation", "unchecked" })
 	public void setup() {
 		this.traceRestClientRibbonCommandFactory = new TraceRestClientRibbonCommandFactory(
-				this.springClientFactory, this.tracer, this.spanInjector);
+				this.springClientFactory, this.tracer, this.spanInjector,
+				httpTraceKeysInjector);
 		given(this.springClientFactory.getClient(anyString(), any(Class.class)))
 				.willReturn(new RestClient());
 		Span span = Span.builder().name("name").spanId(1L).traceId(2L).parent(3L)

spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/zuul/TraceZuulIntegrationTests.java

@@ -0,0 +1,157 @@
+package org.springframework.cloud.sleuth.instrument.zuul;
+
+import java.io.IOException;
+
+import com.netflix.loadbalancer.Server;
+import com.netflix.loadbalancer.ServerList;
+
+import org.junit.Before;
+import org.junit.Test;
+import org.junit.runner.RunWith;
+import org.springframework.beans.factory.annotation.Autowired;
+import org.springframework.beans.factory.annotation.Value;
+import org.springframework.boot.autoconfigure.EnableAutoConfiguration;
+import org.springframework.boot.test.IntegrationTest;
+import org.springframework.boot.test.SpringApplicationConfiguration;
+import org.springframework.cloud.client.discovery.DiscoveryClient;
+import org.springframework.cloud.netflix.ribbon.RibbonClient;
+import org.springframework.cloud.netflix.ribbon.StaticServerList;
+import org.springframework.cloud.netflix.zuul.EnableZuulProxy;
+import org.springframework.cloud.netflix.zuul.filters.RouteLocator;
+import org.springframework.cloud.netflix.zuul.filters.ZuulProperties;
+import org.springframework.cloud.netflix.zuul.filters.discovery.DiscoveryClientRouteLocator;
+import org.springframework.cloud.sleuth.Sampler;
+import org.springframework.cloud.sleuth.Span;
+import org.springframework.cloud.sleuth.SpanReporter;
+import org.springframework.cloud.sleuth.Tracer;
+import org.springframework.cloud.sleuth.assertions.ListOfSpans;
+import org.springframework.cloud.sleuth.sampler.AlwaysSampler;
+import org.springframework.cloud.sleuth.util.ArrayListSpanAccumulator;
+import org.springframework.context.annotation.Bean;
+import org.springframework.context.annotation.Configuration;
+import org.springframework.http.HttpEntity;
+import org.springframework.http.HttpMethod;
+import org.springframework.http.HttpStatus;
+import org.springframework.http.ResponseEntity;
+import org.springframework.http.client.ClientHttpResponse;
+import org.springframework.test.annotation.DirtiesContext;
+import org.springframework.test.context.junit4.SpringJUnit4ClassRunner;
+import org.springframework.test.context.web.WebAppConfiguration;
+import org.springframework.web.bind.annotation.RequestMapping;
+import org.springframework.web.bind.annotation.RestController;
+import org.springframework.web.client.DefaultResponseErrorHandler;
+import org.springframework.web.client.RestTemplate;
+
+import static org.springframework.cloud.sleuth.assertions.SleuthAssertions.then;
+
+@RunWith(SpringJUnit4ClassRunner.class)
+@SpringApplicationConfiguration(classes = SampleZuulProxyApplication.class)
+@WebAppConfiguration
+@IntegrationTest({ "server.port: 0", "zuul.routes.simple: /simple/**", "hystrix.command.default.execution.isolation.strategy: SEMAPHORE"})
+@DirtiesContext
+public class TraceZuulIntegrationTests {
+
+	@Value("${local.server.port}")
+	private int port;
+	@Autowired Tracer tracer;
+	@Autowired ArrayListSpanAccumulator spanAccumulator;
+	@Autowired RestTemplate restTemplate;
+
+	@Before
+	public void cleanup() {
+		this.spanAccumulator.getSpans().clear();
+	}
+
+	@Test
+	public void should_close_span_when_routing_to_service_via_discovery() {
+		Span span = this.tracer.createSpan("new_span");
+		ResponseEntity<String> result = this.restTemplate.exchange(
+				"http://localhost:" + this.port + "/simple/", HttpMethod.GET,
+				new HttpEntity<>((Void) null), String.class);
+
+		this.tracer.close(span);
+
+		then(result.getStatusCode()).isEqualTo(HttpStatus.OK);
+		then(result.getBody()).isEqualTo("Hello world");
+		then(this.tracer.getCurrentSpan()).isNull();
+		then(new ListOfSpans(this.spanAccumulator.getSpans()))
+				.thereIsOnlyOneServerAndClientSideSpanWhoseParentIdIsEqualTo(span.getTraceId());
+	}
+
+	@Test
+	public void should_close_span_when_routing_to_service_via_discovery_to_a_non_existent_url() {
+		Span span = this.tracer.createSpan("new_span");
+		ResponseEntity<String> result = this.restTemplate.exchange(
+				"http://localhost:" + this.port + "/simple/nonExistentUrl", HttpMethod.GET,
+				new HttpEntity<>((Void) null), String.class);
+
+		this.tracer.close(span);
+
+		then(result.getStatusCode()).isEqualTo(HttpStatus.NOT_FOUND);
+		then(this.tracer.getCurrentSpan()).isNull();
+		then(new ListOfSpans(this.spanAccumulator.getSpans()))
+				.thereIsOnlyOneServerAndClientSideSpanWhoseParentIdIsEqualTo(span.getTraceId())
+				.everyParentIdHasItsCorrespondingSpan();
+	}
+}
+
+// Don't use @SpringBootApplication because we don't want to component scan
+@Configuration
+@EnableAutoConfiguration
+@RestController
+@EnableZuulProxy
+@RibbonClient(name = "simple", configuration = SimpleRibbonClientConfiguration.class)
+class SampleZuulProxyApplication {
+
+
+	@RequestMapping("/")
+	public String home() {
+		return "Hello world";
+	}
+
+	@RequestMapping("/exception")
+	public String exception() {
+		throw new RuntimeException();
+	}
+
+	@Bean RouteLocator routeLocator(DiscoveryClient discoveryClient, ZuulProperties zuulProperties) {
+		return new MyRouteLocator("/", discoveryClient, zuulProperties);
+	}
+
+	@Bean SpanReporter testSpanReporter() {
+		return new ArrayListSpanAccumulator();
+	}
+
+	@Bean RestTemplate restTemplate() {
+		RestTemplate restTemplate = new RestTemplate();
+		restTemplate.setErrorHandler(new DefaultResponseErrorHandler() {
+			@Override public void handleError(ClientHttpResponse response)
+					throws IOException {
+
+			}
+		});
+		return restTemplate;
+	}
+
+	@Bean Sampler alwaysSampler() {
+		return new AlwaysSampler();
+	}
+}
+
+class MyRouteLocator extends DiscoveryClientRouteLocator {
+
+	public MyRouteLocator(String servletPath, DiscoveryClient discovery, ZuulProperties properties) {
+		super(servletPath, discovery, properties);
+	}
+}
+
+// Load balancer with fixed server list for "simple" pointing to localhost
+@Configuration
+class SimpleRibbonClientConfiguration {
+
+	@Value("${local.server.port}") private int port;
+
+	@Bean public ServerList<Server> ribbonServerList() {
+		return new StaticServerList<>(new Server("localhost", this.port));
+	}
+}

spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/log/Slf4JSpanLoggerTest.java

@@ -16,11 +16,13 @@
 
 package org.springframework.cloud.sleuth.log;
 
+import org.junit.Before;
 import org.junit.Test;
 import org.mockito.Mockito;
 import org.slf4j.Logger;
 import org.springframework.cloud.sleuth.Span;
 
+import static org.mockito.BDDMockito.given;
 import static org.mockito.BDDMockito.then;
 import static org.mockito.Matchers.anyList;
 import static org.mockito.Matchers.anyString;
@@ -38,6 +40,11 @@ public class Slf4JSpanLoggerTest {
 	Logger log = Mockito.mock(Logger.class);
 	Slf4jSpanLogger slf4JSpanLogger = new Slf4jSpanLogger(this.nameExcludingPattern, this.log);
 
+	@Before
+	public void setup() {
+		given(log.isTraceEnabled()).willReturn(true);
+	}
+
 	@Test
 	public void should_log_when_start_event_arrived_and_pattern_doesnt_match_span_name() throws Exception {
 		this.slf4JSpanLogger.logStartedSpan(this.spanWithNameNotToBeExcluded,

spring-cloud-sleuth-core/src/test/resources/application.yml

@@ -11,4 +11,4 @@ exceptionService.ribbon:
 
 spring.sleuth.scheduled.skipPattern: "^org.*TestBeanWithScheduledMethodToBeIgnored$"
 # comma separated list of matchers
-spring.sleuth.rxjava.schedulers.ignoredthreads: HystixMetricPoller,^MyCustomThread.*$
+spring.sleuth.rxjava.schedulers.ignoredthreads: HystixMetricPoller,^MyCustomThread.*$,^RxComputation.*$

spring-cloud-sleuth-core/src/test/resources/logback.xml

@@ -1,7 +1,10 @@
 <?xml version="1.0" encoding="UTF-8"?>
 <configuration>
 	<include resource="org/springframework/boot/logging/logback/base.xml"/>
-	<logger name="org.springframework.cloud.sleuth" level="DEBUG"/>
+	<logger name="org.springframework.cloud.sleuth" level="TRACE"/>
+	<logger name="org.springframework.cloud.sleuth.log" level="DEBUG"/>
+	<logger name="org.springframework.cloud.sleuth.trace" level="DEBUG"/>
+	<logger name="org.springframework.cloud.sleuth.instrument.rxjava" level="DEBUG"/>
 	<logger name="org.springframework.boot" level="DEBUG"/>
 	<logger name="org.springframework.web" level="DEBUG"/>
 	<root level="INFO">

spring-cloud-sleuth-dependencies/pom.xml

@@ -14,7 +14,7 @@
 	<name>spring-cloud-sleuth-dependencies</name>
 	<description>Spring Cloud Sleuth Dependencies</description>
 	<properties>
-		<spring-cloud-netflix.version>1.1.1.BUILD-SNAPSHOT</spring-cloud-netflix.version>
+		<spring-cloud-netflix.version>1.1.2.BUILD-SNAPSHOT</spring-cloud-netflix.version>
 		<aspectj.version>1.8.4</aspectj.version>
 		<zipkin.version>1.1.1</zipkin.version>
 	</properties>