diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/TraceDelegate.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/TraceDelegate.java index f30a7caf9..026748013 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/TraceDelegate.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/TraceDelegate.java @@ -16,11 +16,12 @@ package org.springframework.cloud.sleuth.instrument; -import lombok.Getter; import org.springframework.cloud.sleuth.Span; import org.springframework.cloud.sleuth.Tracer; import org.springframework.cloud.sleuth.trace.SpanContextHolder; +import lombok.Getter; + /** * @author Spencer Gibb */ @@ -49,9 +50,6 @@ public abstract class TraceDelegate { protected void closeAll(Span span) { span = this.tracer.close(span); - while (span != null) { - span = this.tracer.detach(span); - } } protected Span startSpan() { diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/hystrix/TraceCommand.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/hystrix/TraceCommand.java index e77d80424..531948a8b 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/hystrix/TraceCommand.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/hystrix/TraceCommand.java @@ -16,13 +16,12 @@ package org.springframework.cloud.sleuth.instrument.hystrix; -import com.netflix.hystrix.HystrixCommand; -import com.netflix.hystrix.HystrixCommandGroupKey; -import com.netflix.hystrix.HystrixThreadPoolKey; import org.springframework.cloud.sleuth.Span; import org.springframework.cloud.sleuth.Tracer; import org.springframework.cloud.sleuth.trace.SpanContextHolder; +import com.netflix.hystrix.HystrixCommand; + /** * Abstraction over {@code HystrixCommand} that wraps command execution with Trace setting * @@ -38,30 +37,6 @@ public abstract class TraceCommand extends HystrixCommand { private final Tracer tracer; private final Span parentSpan; - protected TraceCommand(Tracer tracer, HystrixCommandGroupKey group) { - super(group); - this.tracer = tracer; - this.parentSpan = tracer.getCurrentSpan(); - } - - protected TraceCommand(Tracer tracer, HystrixCommandGroupKey group, HystrixThreadPoolKey threadPool) { - super(group, threadPool); - this.tracer = tracer; - this.parentSpan = tracer.getCurrentSpan(); - } - - protected TraceCommand(Tracer tracer, HystrixCommandGroupKey group, int executionIsolationThreadTimeoutInMilliseconds) { - super(group, executionIsolationThreadTimeoutInMilliseconds); - this.tracer = tracer; - this.parentSpan = tracer.getCurrentSpan(); - } - - protected TraceCommand(Tracer tracer, HystrixCommandGroupKey group, HystrixThreadPoolKey threadPool, int executionIsolationThreadTimeoutInMilliseconds) { - super(group, threadPool, executionIsolationThreadTimeoutInMilliseconds); - this.tracer = tracer; - this.parentSpan = tracer.getCurrentSpan(); - } - protected TraceCommand(Tracer tracer, Setter setter) { super(setter); this.tracer = tracer; @@ -74,7 +49,8 @@ public abstract class TraceCommand extends HystrixCommand { Span span = this.tracer.joinTrace(getCommandKey().name(), this.parentSpan); try { return doRun(); - } finally { + } + finally { this.tracer.close(span); } } diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceFilter.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceFilter.java index 7baa373a0..390d122ed 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceFilter.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceFilter.java @@ -105,8 +105,9 @@ public class TraceFilter extends OncePerRequestFilter protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException { - SpanContextHolder.removeCurrentSpan(); + // TODO: this should not be necessary + SpanContextHolder.removeCurrentSpan(); String uri = this.urlPathHelper.getPathWithinApplication(request); boolean skip = this.skipPattern.matcher(uri).matches() || getHeader(request, response, Span.NOT_SAMPLED_NAME) != null; @@ -195,7 +196,7 @@ public class TraceFilter extends OncePerRequestFilter spanFromRequest)); } // Double close to clean up the parent (remote span as well) - this.tracer.close(this.tracer.close(spanFromRequest)); + this.tracer.close(spanFromRequest); } } } diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/trace/DefaultTracer.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/trace/DefaultTracer.java index 3d8044e19..8210a64ec 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/trace/DefaultTracer.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/trace/DefaultTracer.java @@ -16,8 +16,6 @@ package org.springframework.cloud.sleuth.trace; -import static org.springframework.cloud.sleuth.util.ExceptionUtils.warn; - import java.util.Random; import java.util.concurrent.Callable; @@ -55,11 +53,6 @@ public class DefaultTracer implements Tracer { if (parent == null) { return startTrace(name); } - Span currentSpan = getCurrentSpan(); - if (currentSpan != null && !parent.equals(currentSpan)) { - warn("Tried to start a new Span with parent " + parent - + ", but there is already a " + "currentSpan " + currentSpan); - } return continueSpan(createChild(parent, name)); } @@ -100,12 +93,7 @@ public class DefaultTracer implements Tracer { + ". You may have forgotten to close or detach " + cur); } else { - if (span.hasSavedSpan()) { - SpanContextHolder.setCurrentSpan(span.getSavedSpan()); - } - else { - SpanContextHolder.removeCurrentSpan(); - } + SpanContextHolder.removeCurrentSpan(); } return span.getSavedSpan(); } @@ -126,14 +114,13 @@ public class DefaultTracer implements Tracer { span.stop(); if (savedSpan != null && span.getParents().contains(savedSpan.getSpanId())) { this.publisher.publishEvent(new SpanReleasedEvent(this, savedSpan, span)); - SpanContextHolder.setCurrentSpan(savedSpan); } else { if (!span.isRemote()) { this.publisher.publishEvent(new SpanReleasedEvent(this, span)); } - SpanContextHolder.removeCurrentSpan(); } + SpanContextHolder.close(); } return savedSpan; } @@ -148,13 +135,12 @@ public class DefaultTracer implements Tracer { } else { if (SpanContextHolder.getCurrentSpan() == null) { - Span span = createSpan(parent, null); - SpanContextHolder.setCurrentSpan(span); + SpanContextHolder.push(parent, true); } Span span = Span.builder().begin(System.currentTimeMillis()).name(name) .traceId(parent.getTraceId()).parent(parent.getSpanId()).spanId(id) - .processId(parent.getProcessId()).exportable(parent.isExportable()) - .build(); + .processId(parent.getProcessId()).savedSpan(parent) + .exportable(parent.isExportable()).build(); this.publisher.publishEvent(new SpanAcquiredEvent(this, parent, span)); return span; } diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/trace/SpanContextHolder.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/trace/SpanContextHolder.java index 3a6d0b14b..47b515e5e 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/trace/SpanContextHolder.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/trace/SpanContextHolder.java @@ -16,20 +16,22 @@ package org.springframework.cloud.sleuth.trace; -import lombok.extern.apachecommons.CommonsLog; import org.springframework.cloud.sleuth.Span; import org.springframework.core.NamedThreadLocal; +import lombok.extern.apachecommons.CommonsLog; + /** * @author Spencer Gibb */ @CommonsLog public class SpanContextHolder { - private static final ThreadLocal CURRENT_SPAN = new NamedThreadLocal<>("Trace Context"); + private static final ThreadLocal CURRENT_SPAN = new NamedThreadLocal<>( + "Trace Context"); public static Span getCurrentSpan() { - return isTracing() ? CURRENT_SPAN.get() : null; + return isTracing() ? CURRENT_SPAN.get().span : null; } public static void setCurrentSpan(Span span) { @@ -41,7 +43,7 @@ public class SpanContextHolder { if (log.isTraceEnabled()) { log.trace("Setting current span " + span); } - CURRENT_SPAN.set(span); + push(span, false); } public static void removeCurrentSpan() { @@ -51,4 +53,47 @@ public class SpanContextHolder { public static boolean isTracing() { return CURRENT_SPAN.get() != null; } + + /** + * Close the current span and all parents that can be auto closed. + */ + static void close() { + SpanContext current = CURRENT_SPAN.get(); + CURRENT_SPAN.remove(); + while (current != null) { + current = current.parent; + if (current != null) { + if (!current.autoClose) { + CURRENT_SPAN.set(current); + current = null; + } + } + } + } + + static void push(Span span, boolean autoClose) { + if (isCurrent(span)) { + return; + } + CURRENT_SPAN.set(new SpanContext(span, autoClose)); + } + + private static boolean isCurrent(Span span) { + if (span == null || CURRENT_SPAN.get() == null) { + return false; + } + return span.equals(CURRENT_SPAN.get().span); + } + + private static class SpanContext { + Span span; + boolean autoClose; + SpanContext parent; + + public SpanContext(Span span, boolean autoClose) { + this.span = span; + this.autoClose = autoClose; + this.parent = CURRENT_SPAN.get(); + } + } } diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/AdhocTestSuite.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/AdhocTestSuite.java index 720b9fbba..73e52487b 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/AdhocTestSuite.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/AdhocTestSuite.java @@ -20,8 +20,8 @@ import org.junit.Ignore; import org.junit.runner.RunWith; import org.junit.runners.Suite; import org.junit.runners.Suite.SuiteClasses; -import org.springframework.cloud.sleuth.instrument.TraceRunnableTests; -import org.springframework.cloud.sleuth.template.TraceTemplateTests; +import org.springframework.cloud.sleuth.instrument.hystrix.SpanPassingForHystrixViaAnnotationsIntegrationTests; +import org.springframework.cloud.sleuth.instrument.hystrix.TraceCommandTests; /** * A test suite for probing weird ordering problems in the tests. @@ -29,8 +29,8 @@ import org.springframework.cloud.sleuth.template.TraceTemplateTests; * @author Dave Syer */ @RunWith(Suite.class) -@SuiteClasses({ TraceTemplateTests.class, - TraceRunnableTests.class }) +@SuiteClasses({ SpanPassingForHystrixViaAnnotationsIntegrationTests.class, + TraceCommandTests.class }) @Ignore public class AdhocTestSuite { diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/hystrix/SpanPassingForHystrixViaAnnotationsIntegrationTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/hystrix/SpanPassingForHystrixViaAnnotationsIntegrationTests.java index a87e9ce6c..00008803c 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/hystrix/SpanPassingForHystrixViaAnnotationsIntegrationTests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/hystrix/SpanPassingForHystrixViaAnnotationsIntegrationTests.java @@ -1,7 +1,9 @@ package org.springframework.cloud.sleuth.instrument.hystrix; -import com.jayway.awaitility.Awaitility; -import com.netflix.hystrix.contrib.javanica.annotation.HystrixCommand; +import static org.springframework.cloud.sleuth.assertions.SleuthAssertions.then; + +import java.util.concurrent.atomic.AtomicReference; + import org.junit.After; import org.junit.Test; import org.junit.runner.RunWith; @@ -14,21 +16,27 @@ import org.springframework.cloud.sleuth.instrument.DefaultTestAutoConfiguration; import org.springframework.cloud.sleuth.trace.SpanContextHolder; import org.springframework.context.annotation.Bean; import org.springframework.context.annotation.Configuration; +import org.springframework.test.context.TestPropertySource; import org.springframework.test.context.junit4.SpringJUnit4ClassRunner; -import java.util.concurrent.atomic.AtomicReference; - -import static org.springframework.cloud.sleuth.assertions.SleuthAssertions.then; +import com.jayway.awaitility.Awaitility; +import com.netflix.hystrix.contrib.javanica.annotation.HystrixCommand; @RunWith(SpringJUnit4ClassRunner.class) @SpringApplicationConfiguration(classes = { SpanPassingForHystrixViaAnnotationsIntegrationTests.TestConfig.class }) +@TestPropertySource(properties="hystrix.command.default.execution.isolation.thread.timeoutInMilliseconds=1000000") public class SpanPassingForHystrixViaAnnotationsIntegrationTests { @Autowired HystrixCommandInvocationSpanCatcher hystrixCommandInvocationSpanCatcher; @Autowired Tracer tracer; + @After + public void clean() { + SpanContextHolder.removeCurrentSpan(); + } + @Test public void should_set_span_on_an_hystrix_command_annotated_method() { Span span = givenASpanInCurrentThread(); diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/hystrix/TraceCommandTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/hystrix/TraceCommandTests.java index 718bc7a1a..59f48a1c4 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/hystrix/TraceCommandTests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/hystrix/TraceCommandTests.java @@ -1,7 +1,11 @@ package org.springframework.cloud.sleuth.instrument.hystrix; -import com.netflix.hystrix.HystrixCommandKey; -import com.netflix.hystrix.HystrixThreadPoolProperties; +import static com.netflix.hystrix.HystrixCommand.Setter.withGroupKey; +import static com.netflix.hystrix.HystrixCommandGroupKey.Factory.asKey; +import static org.assertj.core.api.BDDAssertions.then; + +import java.util.Random; + import org.junit.After; import org.junit.Before; import org.junit.Test; @@ -13,17 +17,14 @@ import org.springframework.cloud.sleuth.trace.DefaultTracer; import org.springframework.cloud.sleuth.trace.SpanContextHolder; import org.springframework.context.ApplicationEventPublisher; -import java.util.Random; - -import static com.netflix.hystrix.HystrixCommand.Setter.withGroupKey; -import static com.netflix.hystrix.HystrixCommandGroupKey.Factory.asKey; -import static org.assertj.core.api.BDDAssertions.then; +import com.netflix.hystrix.HystrixCommandProperties; +import com.netflix.hystrix.HystrixThreadPoolProperties; public class TraceCommandTests { static final long EXPECTED_TRACE_ID = 1L; - Tracer tracer = new DefaultTracer(new AlwaysSampler(), - new Random(), Mockito.mock(ApplicationEventPublisher.class)); + Tracer tracer = new DefaultTracer(new AlwaysSampler(), new Random(), + Mockito.mock(ApplicationEventPublisher.class)); @Before public void setup() { @@ -38,15 +39,14 @@ public class TraceCommandTests { @Test public void should_remove_span_from_thread_local_after_finishing_work() throws Exception { - SpanContextHolder.removeCurrentSpan(); Span firstSpanFromHystrix = givenACommandWasExecuted(traceReturningCommand()); Span secondSpanFromHystrix = whenCommandIsExecuted(traceReturningCommand()); - then(secondSpanFromHystrix.getTraceId()).as("second span id") - .isNotEqualTo(firstSpanFromHystrix.getTraceId()).as("first span id"); - then(secondSpanFromHystrix.getSavedSpan()).as("saved span as remnant of first span") - .isNull(); + then(secondSpanFromHystrix.getTraceId()).as("second trace id") + .isNotEqualTo(firstSpanFromHystrix.getTraceId()).as("first trace id"); + then(secondSpanFromHystrix.getSavedSpan()) + .as("saved span as remnant of first span").isNull(); } @Test @@ -66,14 +66,17 @@ public class TraceCommandTests { } private Span givenATraceIsPresentInTheCurrentThread() { - return this.tracer - .joinTrace("test", Span.builder().traceId(EXPECTED_TRACE_ID).build()); + return this.tracer.joinTrace("test", + Span.builder().traceId(EXPECTED_TRACE_ID).build()); } private TraceCommand traceReturningCommand() { - return new TraceCommand(this.tracer, withGroupKey(asKey("")) - .andCommandKey(HystrixCommandKey.Factory.asKey("")).andThreadPoolPropertiesDefaults( - HystrixThreadPoolProperties.Setter().withMaxQueueSize(1).withCoreSize(1))) { + return new TraceCommand(this.tracer, + withGroupKey(asKey("group")) + .andThreadPoolPropertiesDefaults(HystrixThreadPoolProperties + .Setter().withCoreSize(1).withMaxQueueSize(1)) + .andCommandPropertiesDefaults(HystrixCommandProperties.Setter() + .withExecutionTimeoutEnabled(false))) { @Override public Span doRun() throws Exception { return SpanContextHolder.getCurrentSpan();