From a44bb543545187dbac7f35eeb8a6bff0f7d40c5a Mon Sep 17 00:00:00 2001 From: Marcin Grzejszczak Date: Fri, 17 Nov 2017 12:35:59 +0100 Subject: [PATCH] Continuation of async spans (#784) without this change, we always create a new span in TraceAsyncAspect. That's because the span created via LazyTraceExecutor (which is executed before the aspect), contains no useful information. with this change we're renaming the LTE span in TraceAsyncAspect. We're using an InternalApi class that we kindly ask that nobody uses. fixes #661 #783 --- .../cloud/sleuth/InternalApi.java | 14 ++++++++ .../springframework/cloud/sleuth/Span.java | 2 +- .../async/AsyncDefaultAutoConfiguration.java | 5 +-- .../instrument/async/TraceAsyncAspect.java | 34 ++++++++++++++++--- .../cloud/sleuth/InternalApiTests.java | 19 +++++++++++ .../async/ExecutorBeanPostProcessorTests.java | 2 +- .../reactor/SpanSubscriberTests.java | 1 - .../web/TraceAsyncIntegrationTests.java | 34 ++++++++++++++++++- 8 files changed, 101 insertions(+), 10 deletions(-) create mode 100644 spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/InternalApi.java create mode 100644 spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/InternalApiTests.java diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/InternalApi.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/InternalApi.java new file mode 100644 index 000000000..a3db0ce1f --- /dev/null +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/InternalApi.java @@ -0,0 +1,14 @@ +package org.springframework.cloud.sleuth; + +/** + * Internal API that can be changed any time so please do not use it! + * + * @author Marcin Grzejszczak + * @since 2.0.0 + */ +public class InternalApi { + + public static void renameSpan(Span span, String newName) { + span.name = newName; + } +} diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/Span.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/Span.java index 9354644c3..4c254b9e9 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/Span.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/Span.java @@ -143,7 +143,7 @@ public class Span implements SpanContext { private final long begin; private long end = 0; - private final String name; + volatile String name; private final long traceIdHigh; private final long traceId; private List parents = new ArrayList<>(); diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/async/AsyncDefaultAutoConfiguration.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/async/AsyncDefaultAutoConfiguration.java index 1e8420171..c57005e76 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/async/AsyncDefaultAutoConfiguration.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/async/AsyncDefaultAutoConfiguration.java @@ -24,6 +24,7 @@ import org.springframework.boot.autoconfigure.AutoConfigureAfter; import org.springframework.boot.autoconfigure.condition.ConditionalOnBean; import org.springframework.boot.autoconfigure.condition.ConditionalOnMissingBean; import org.springframework.boot.autoconfigure.condition.ConditionalOnProperty; +import org.springframework.cloud.sleuth.SpanNamer; import org.springframework.cloud.sleuth.TraceKeys; import org.springframework.cloud.sleuth.Tracer; import org.springframework.context.annotation.Bean; @@ -65,8 +66,8 @@ public class AsyncDefaultAutoConfiguration { } @Bean - public TraceAsyncAspect traceAsyncAspect(Tracer tracer, TraceKeys traceKeys) { - return new TraceAsyncAspect(tracer, traceKeys, this.beanFactory); + public TraceAsyncAspect traceAsyncAspect(Tracer tracer, TraceKeys traceKeys, SpanNamer spanNamer) { + return new TraceAsyncAspect(tracer, traceKeys, spanNamer); } @Bean diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/async/TraceAsyncAspect.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/async/TraceAsyncAspect.java index 2d92887f5..1ea139f94 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/async/TraceAsyncAspect.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/async/TraceAsyncAspect.java @@ -16,11 +16,14 @@ package org.springframework.cloud.sleuth.instrument.async; +import java.lang.reflect.Method; + import org.aspectj.lang.ProceedingJoinPoint; import org.aspectj.lang.annotation.Around; import org.aspectj.lang.annotation.Aspect; import org.aspectj.lang.reflect.MethodSignature; import org.springframework.beans.factory.BeanFactory; +import org.springframework.cloud.sleuth.InternalApi; import org.springframework.cloud.sleuth.Span; import org.springframework.cloud.sleuth.SpanNamer; import org.springframework.cloud.sleuth.TraceKeys; @@ -28,8 +31,6 @@ import org.springframework.cloud.sleuth.Tracer; import org.springframework.cloud.sleuth.util.SpanNameUtil; import org.springframework.util.ReflectionUtils; -import java.lang.reflect.Method; - /** * Aspect that creates a new Span for running threads executing methods annotated with * {@link org.springframework.scheduling.annotation.Async} annotation. @@ -49,17 +50,26 @@ public class TraceAsyncAspect { private final BeanFactory beanFactory; private SpanNamer spanNamer; + @Deprecated public TraceAsyncAspect(Tracer tracer, TraceKeys traceKeys, BeanFactory beanFactory) { this.tracer = tracer; this.traceKeys = traceKeys; this.beanFactory = beanFactory; } + public TraceAsyncAspect(Tracer tracer, TraceKeys traceKeys, SpanNamer spanNamer) { + this.tracer = tracer; + this.traceKeys = traceKeys; + this.spanNamer = spanNamer; + this.beanFactory = null; + } + @Around("execution (@org.springframework.scheduling.annotation.Async * *.*(..))") public Object traceBackgroundThread(final ProceedingJoinPoint pjp) throws Throwable { String spanName = spanNamer().name(getMethod(pjp, pjp.getTarget()), SpanNameUtil.toLowerHyphen(pjp.getSignature().getName())); - Span span = this.tracer.createSpan(spanName); + Span span = span(spanName); + renameAsyncSpan(spanName, span); this.tracer.addTag(Span.SPAN_LOCAL_COMPONENT_TAG_NAME, ASYNC_COMPONENT); this.tracer.addTag(this.traceKeys.getAsync().getPrefix() + this.traceKeys.getAsync().getClassNameKey(), pjp.getTarget().getClass().getSimpleName()); @@ -72,6 +82,22 @@ public class TraceAsyncAspect { } } + private void renameAsyncSpan(String spanName, Span span) { + // if there's a tag "lc" -> "async", that means the span came from + // a LazyTraceExecutor component that creates a span that contains very few + // information. If that's the case we want to rename it to have a different name + if (ASYNC_COMPONENT.equals(span.tags().get(Span.SPAN_LOCAL_COMPONENT_TAG_NAME))) { + InternalApi.renameSpan(span, spanName); + } + } + + private Span span(String spanName) { + if (this.tracer.isTracing()) { + return this.tracer.getCurrentSpan(); + } + return this.tracer.createSpan(spanName); + } + private Method getMethod(ProceedingJoinPoint pjp, Object object) { MethodSignature signature = (MethodSignature) pjp.getSignature(); Method method = signature.getMethod(); @@ -80,7 +106,7 @@ public class TraceAsyncAspect { } SpanNamer spanNamer() { - if (this.spanNamer == null) { + if (this.spanNamer == null && this.beanFactory != null) { this.spanNamer = this.beanFactory.getBean(SpanNamer.class); } return this.spanNamer; diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/InternalApiTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/InternalApiTests.java new file mode 100644 index 000000000..154f70727 --- /dev/null +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/InternalApiTests.java @@ -0,0 +1,19 @@ +package org.springframework.cloud.sleuth; + +import org.assertj.core.api.BDDAssertions; +import org.junit.Test; + +/** + * @author Marcin Grzejszczak + */ +public class InternalApiTests { + + @Test + public void should_rename_a_span() { + Span span = Span.builder().name("foo").build(); + + InternalApi.renameSpan(span, "bar"); + + BDDAssertions.then(span.getName()).isEqualTo("bar"); + } +} \ No newline at end of file diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/async/ExecutorBeanPostProcessorTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/async/ExecutorBeanPostProcessorTests.java index 90179ce64..48dd6632e 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/async/ExecutorBeanPostProcessorTests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/async/ExecutorBeanPostProcessorTests.java @@ -7,7 +7,7 @@ import java.util.concurrent.ScheduledExecutorService; import org.junit.Test; import org.junit.runner.RunWith; import org.mockito.Mock; -import org.mockito.runners.MockitoJUnitRunner; +import org.mockito.junit.MockitoJUnitRunner; import org.springframework.aop.framework.AopConfigException; import org.springframework.beans.factory.BeanFactory; import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor; diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/reactor/SpanSubscriberTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/reactor/SpanSubscriberTests.java index 7e39f6413..33aaf4122 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/reactor/SpanSubscriberTests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/reactor/SpanSubscriberTests.java @@ -69,7 +69,6 @@ public class SpanSubscriberTests { then(ExceptionUtils.getLastException()).isNull(); } - @Ignore("Ignored until fixed in Reactor") @Test public void should_support_reactor_fusion_optimization() { Span span = this.tracer.createSpan("foo"); final AtomicReference spanInOperation = new AtomicReference<>(); diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceAsyncIntegrationTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceAsyncIntegrationTests.java index 52b93e165..054c9c0b0 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceAsyncIntegrationTests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceAsyncIntegrationTests.java @@ -44,6 +44,20 @@ public class TraceAsyncIntegrationTests { @Test public void should_set_span_on_an_async_annotated_method() { + whenAsyncProcessingTakesPlace(); + + thenANewAsyncSpanGetsCreated(); + } + + @Test + public void should_set_span_with_custom_method_on_an_async_annotated_method() { + whenAsyncProcessingTakesPlaceWithCustomSpanName(); + + thenAsyncSpanHasCustomName(); + } + + @Test + public void should_continue_a_span_on_an_async_annotated_method() { Span span = givenASpanInCurrentThread(); whenAsyncProcessingTakesPlace(); @@ -53,7 +67,7 @@ public class TraceAsyncIntegrationTests { } @Test - public void should_set_span_with_custom_method_on_an_async_annotated_method() { + public void should_continue_a_span_with_custom_method_on_an_async_annotated_method() { Span span = givenASpanInCurrentThread(); whenAsyncProcessingTakesPlaceWithCustomSpanName(); @@ -78,6 +92,15 @@ public class TraceAsyncIntegrationTests { Awaitility.await().atMost(5, SECONDS).untilAsserted( () -> then(TraceAsyncIntegrationTests.this.classPerformingAsyncLogic.getSpan()) .hasTraceIdEqualTo(span.getTraceId()) + .hasNameEqualTo("http:existing") + .isALocalComponentSpan() + .hasATag("class", "ClassPerformingAsyncLogic") + .hasATag("method", "invokeAsynchronousLogic")); + } + + private void thenANewAsyncSpanGetsCreated() { + Awaitility.await().atMost(5, SECONDS).untilAsserted( + () -> then(TraceAsyncIntegrationTests.this.classPerformingAsyncLogic.getSpan()) .hasNameEqualTo("invoke-asynchronous-logic") .isALocalComponentSpan() .hasATag("class", "ClassPerformingAsyncLogic") @@ -88,6 +111,15 @@ public class TraceAsyncIntegrationTests { Awaitility.await().atMost(5, SECONDS).untilAsserted( () -> then(TraceAsyncIntegrationTests.this.classPerformingAsyncLogic.getSpan()) .hasTraceIdEqualTo(span.getTraceId()) + .hasNameEqualTo("http:existing") + .isALocalComponentSpan() + .hasATag("class", "ClassPerformingAsyncLogic") + .hasATag("method", "customNameInvokeAsynchronousLogic")); + } + + private void thenAsyncSpanHasCustomName() { + Awaitility.await().atMost(5, SECONDS).untilAsserted( + () -> then(TraceAsyncIntegrationTests.this.classPerformingAsyncLogic.getSpan()) .hasNameEqualTo("foo") .isALocalComponentSpan() .hasATag("class", "ClassPerformingAsyncLogic")