From 7f012ac02c7db4b40262917df0a5392fb6cd6225 Mon Sep 17 00:00:00 2001 From: Dave Syer Date: Thu, 4 Feb 2016 12:30:25 +0000 Subject: [PATCH] Introduce SpanContext as internal detail of SpanContextHolder The fact that a Span was active when a new one is created needs to be recorded, but it doesn't seem to belong in the Span. However the DefaultTracer can call other methods on the SpanContextHolder and that's what this change does (with package private methods). There are still some usages of the public methods in SpanContextHolder which I'd like to stamp out as a separate issue. Fixes gh-141 --- .../sleuth/instrument/TraceDelegate.java | 6 +-- .../instrument/hystrix/TraceCommand.java | 32 ++--------- .../sleuth/instrument/web/TraceFilter.java | 5 +- .../cloud/sleuth/trace/DefaultTracer.java | 24 ++------- .../cloud/sleuth/trace/SpanContextHolder.java | 53 +++++++++++++++++-- .../cloud/sleuth/AdhocTestSuite.java | 8 +-- ...HystrixViaAnnotationsIntegrationTests.java | 18 +++++-- .../instrument/hystrix/TraceCommandTests.java | 41 +++++++------- 8 files changed, 102 insertions(+), 85 deletions(-) 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();