diff --git a/spring-cloud-sleuth-instrumentation/src/main/java/org/springframework/cloud/sleuth/instrument/tx/TracePlatformTransactionManager.java b/spring-cloud-sleuth-instrumentation/src/main/java/org/springframework/cloud/sleuth/instrument/tx/TracePlatformTransactionManager.java index 9cd9d6367..4d32c21c0 100644 --- a/spring-cloud-sleuth-instrumentation/src/main/java/org/springframework/cloud/sleuth/instrument/tx/TracePlatformTransactionManager.java +++ b/spring-cloud-sleuth-instrumentation/src/main/java/org/springframework/cloud/sleuth/instrument/tx/TracePlatformTransactionManager.java @@ -70,7 +70,7 @@ public class TracePlatformTransactionManager implements PlatformTransactionManag try { TransactionDefinition def = (definition != null ? definition : TransactionDefinition.withDefaults()); TransactionStatus status = this.delegate.getTransaction(definition); - span = taggedSpan(currentSpan, span, def, status); + taggedSpan(currentSpan, span, def, status); return status; } catch (Exception e) { @@ -127,7 +127,7 @@ public class TracePlatformTransactionManager implements PlatformTransactionManag } finally { SleuthTxSpan.TX_SPAN.wrap(span).event(SleuthTxSpan.Events.COMMIT); - span.end(); + spanAndScope.close(); if (ex == null) { if (log.isDebugEnabled()) { log.debug("No exception was found - will clear thread local span"); @@ -160,7 +160,7 @@ public class TracePlatformTransactionManager implements PlatformTransactionManag } finally { SleuthTxSpan.TX_SPAN.wrap(span).event(SleuthTxSpan.Events.ROLLBACK); - span.end(); + spanAndScope.close(); this.threadLocalSpan.remove(); } } diff --git a/spring-cloud-sleuth-instrumentation/src/main/java/org/springframework/cloud/sleuth/instrument/tx/TraceReactiveTransactionManager.java b/spring-cloud-sleuth-instrumentation/src/main/java/org/springframework/cloud/sleuth/instrument/tx/TraceReactiveTransactionManager.java index b90e24dee..84889e217 100644 --- a/spring-cloud-sleuth-instrumentation/src/main/java/org/springframework/cloud/sleuth/instrument/tx/TraceReactiveTransactionManager.java +++ b/spring-cloud-sleuth-instrumentation/src/main/java/org/springframework/cloud/sleuth/instrument/tx/TraceReactiveTransactionManager.java @@ -74,6 +74,9 @@ public class TraceReactiveTransactionManager implements ReactiveTransactionManag return Mono.deferContextual(contextView -> this.delegate.getReactiveTransaction(definition).map(tx -> { Span span = SleuthTxSpan.TX_SPAN.wrap(span(contextView)); if (tx.isNewTransaction() || span == null) { + if (log.isDebugEnabled()) { + log.debug("New transaction is required"); + } if (span == null) { span = SleuthTxSpan.TX_SPAN.wrap(tracer().nextSpan()).name(SleuthTxSpan.TX_SPAN.getName()).start(); } @@ -82,9 +85,14 @@ public class TraceReactiveTransactionManager implements ReactiveTransactionManag .start(); } TracePlatformTransactionManagerTags.tag(span, definition, this.delegate.getClass()); + } else if (log.isDebugEnabled()) { + log.debug("Will continue the transaction for span [" + span + "]"); } Tracer.SpanInScope withSpan = tracer().withSpan(span); SpanAndScope spanAndScope = new SpanAndScope(span, withSpan); + if (log.isDebugEnabled()) { + log.debug("Got transaction for span [" + spanAndScope + "]"); + } return new TraceReactiveTransaction(tx, spanAndScope); })); } @@ -122,14 +130,13 @@ public class TraceReactiveTransactionManager implements ReactiveTransactionManag TraceReactiveTransaction reactiveTransaction = (TraceReactiveTransaction) transaction; SpanAndScope spanAndScope = reactiveTransaction.spanAndScope; Span span = spanAndScope.getSpan(); - Tracer.SpanInScope scope = spanAndScope.getScope(); + if (log.isDebugEnabled()) { + log.debug("Commiting the transaction for span [" + spanAndScope + "]"); + } return this.delegate.commit(reactiveTransaction.delegate) // TODO: Fix me when this is resolved in Reactor // .doOnSubscribe(__ -> scope.close()) - .doOnError(span::error).doOnSuccess(signalType -> { - span.end(); - scope.close(); - }); + .doOnError(span::error).doOnSuccess(signalType -> spanAndScope.close()); } @Override @@ -140,16 +147,13 @@ public class TraceReactiveTransactionManager implements ReactiveTransactionManag TraceReactiveTransaction reactiveTransaction = (TraceReactiveTransaction) transaction; SpanAndScope spanAndScope = reactiveTransaction.spanAndScope; Span span = spanAndScope.getSpan(); - Tracer.SpanInScope scope = spanAndScope.getScope(); + if (log.isDebugEnabled()) { + log.debug("Rolling back the transaction for span [" + spanAndScope + "]"); + } return this.delegate.rollback(reactiveTransaction.delegate) // TODO: Fix me when this is resolved in Reactor // .doOnSubscribe(__ -> scope.close()) - .doOnError(span::error).doFinally(signalType -> { - span.end(); - if (scope != null) { - scope.close(); - } - }); + .doOnError(span::error).doFinally(signalType -> spanAndScope.close()); } static class TraceReactiveTransaction implements ReactiveTransaction { diff --git a/spring-cloud-sleuth-instrumentation/src/test/java/org/springframework/cloud/sleuth/instrument/tx/TracePlatformTransactionManagerTests.java b/spring-cloud-sleuth-instrumentation/src/test/java/org/springframework/cloud/sleuth/instrument/tx/TracePlatformTransactionManagerTests.java index 5f2e21732..46ab12e32 100644 --- a/spring-cloud-sleuth-instrumentation/src/test/java/org/springframework/cloud/sleuth/instrument/tx/TracePlatformTransactionManagerTests.java +++ b/spring-cloud-sleuth-instrumentation/src/test/java/org/springframework/cloud/sleuth/instrument/tx/TracePlatformTransactionManagerTests.java @@ -56,6 +56,8 @@ class TracePlatformTransactionManagerTests { manager.commit(transaction); // then thenOneSpanWasReported(manager, span); + thenThreadLocalIsClear(manager); + then(tracer.currentSpan()).isNull(); } @Test @@ -74,6 +76,8 @@ class TracePlatformTransactionManagerTests { manager.rollback(transaction); // then thenOneSpanWasReported(manager, span); + thenThreadLocalIsClear(manager); + then(tracer.currentSpan()).isNull(); } @Test @@ -97,6 +101,7 @@ class TracePlatformTransactionManagerTests { then(firstSpan).isSameAs(manager.threadLocalSpan.get().getSpan()); manager.threadLocalSpan.remove(); thenThreadLocalIsClear(manager); + then(tracer.currentSpan()).isNull(); } private SimpleSpan threadLocalSpan(TracePlatformTransactionManager manager) { @@ -130,6 +135,7 @@ class TracePlatformTransactionManagerTests { then(span.throwable).isInstanceOf(TransactionTimedOutException.class); manager.threadLocalSpan.remove(); thenThreadLocalIsClear(manager); + then(tracer.currentSpan()).isNull(); } @Test @@ -144,6 +150,7 @@ class TracePlatformTransactionManagerTests { then(span.throwable).isInstanceOf(TransactionTimedOutException.class); manager.threadLocalSpan.remove(); thenThreadLocalIsClear(manager); + then(tracer.currentSpan()).isNull(); } private void setupTransactionStatusWithNewTransactionStatusEqualTo(boolean transactionStatus) { diff --git a/spring-cloud-sleuth-instrumentation/src/test/java/org/springframework/cloud/sleuth/tracer/SimpleTracer.java b/spring-cloud-sleuth-instrumentation/src/test/java/org/springframework/cloud/sleuth/tracer/SimpleTracer.java index b45eae299..a7156be76 100644 --- a/spring-cloud-sleuth-instrumentation/src/test/java/org/springframework/cloud/sleuth/tracer/SimpleTracer.java +++ b/spring-cloud-sleuth-instrumentation/src/test/java/org/springframework/cloud/sleuth/tracer/SimpleTracer.java @@ -41,6 +41,8 @@ public class SimpleTracer implements Tracer { public List spans = new ArrayList<>(); + public Span currentSpan; + @Override public Span nextSpan(Span parent) { SimpleSpan span = nextSpan(); @@ -65,7 +67,8 @@ public class SimpleTracer implements Tracer { @Override public SpanInScope withSpan(Span span) { - return new NoOpSpanInScope(); + this.currentSpan = span; + return () -> currentSpan = null; } @Override @@ -75,10 +78,7 @@ public class SimpleTracer implements Tracer { @Override public Span currentSpan() { - if (this.spans.isEmpty()) { - return null; - } - return this.spans.get(spans.size() - 1); + return this.currentSpan; } @Override diff --git a/spring-cloud-sleuth-instrumentation/src/test/kotlin/org/springframework/cloud/sleuth/instrument/kotlin/AsContextElementKtTests.kt b/spring-cloud-sleuth-instrumentation/src/test/kotlin/org/springframework/cloud/sleuth/instrument/kotlin/AsContextElementKtTests.kt index 200992bd6..cfefbec86 100644 --- a/spring-cloud-sleuth-instrumentation/src/test/kotlin/org/springframework/cloud/sleuth/instrument/kotlin/AsContextElementKtTests.kt +++ b/spring-cloud-sleuth-instrumentation/src/test/kotlin/org/springframework/cloud/sleuth/instrument/kotlin/AsContextElementKtTests.kt @@ -38,6 +38,7 @@ internal class AsContextElementKtTests { fun `should return current span from context`(): Unit = runBlocking { val simpleTracer = SimpleTracer() val nextSpan = simpleTracer.nextSpan().start() + val inScope = simpleTracer.withSpan(nextSpan) var spanInGlobalScopeLaunch: Span? = null var spanInGlobalScopeAsync: Span? = null val asContextElement = simpleTracer.asContextElement() @@ -49,6 +50,8 @@ internal class AsContextElementKtTests { spanInGlobalScopeAsync = coroutineContext.currentSpan() }.await() + inScope.close(); + then(spanInGlobalScopeLaunch).isSameAs(nextSpan) then(spanInGlobalScopeAsync).isSameAs(nextSpan) } @@ -57,9 +60,11 @@ internal class AsContextElementKtTests { fun `should return span from coroutine context when KotlinContextElement present`(): Unit = runBlocking { val simpleTracer = SimpleTracer() val nextSpan = simpleTracer.nextSpan().start() + val inScope = simpleTracer.withSpan(nextSpan) val element = KotlinContextElement(simpleTracer) then(element.currentSpan()).isSameAs(nextSpan) + inScope.close() } @Test @@ -87,9 +92,11 @@ internal class AsContextElementKtTests { val currentTraceContext = SimpleCurrentTraceContext() val simpleTracer = SimpleTracer() val nextSpan = simpleTracer.nextSpan().start() + val inScope = simpleTracer.withSpan(nextSpan) val reactorContext = ReactorContext(Context.of(Tracer::class.java, simpleTracer, CurrentTraceContext::class.java, currentTraceContext, TraceContext::class.java, nextSpan.context())) then(reactorContext.currentSpan()).isSameAs(nextSpan); + inScope.close() } @Test @@ -97,8 +104,10 @@ internal class AsContextElementKtTests { val simpleTracer = SimpleTracer() val nextSpan = simpleTracer.nextSpan().start() val reactorContext = ReactorContext(Context.of(Tracer::class.java, simpleTracer)) + val inScope = simpleTracer.withSpan(nextSpan) then(reactorContext.currentSpan()).isSameAs(nextSpan); + inScope.close() } @Test diff --git a/tests/brave/spring-cloud-sleuth-instrumentation-r2dbc-tests/src/test/java/org/springframework/cloud/sleuth/brave/instrument/r2dbc/R2dbcIntegrationTests.java b/tests/brave/spring-cloud-sleuth-instrumentation-r2dbc-tests/src/test/java/org/springframework/cloud/sleuth/brave/instrument/r2dbc/R2dbcIntegrationTests.java index c3e825fd1..300efc3a6 100644 --- a/tests/brave/spring-cloud-sleuth-instrumentation-r2dbc-tests/src/test/java/org/springframework/cloud/sleuth/brave/instrument/r2dbc/R2dbcIntegrationTests.java +++ b/tests/brave/spring-cloud-sleuth-instrumentation-r2dbc-tests/src/test/java/org/springframework/cloud/sleuth/brave/instrument/r2dbc/R2dbcIntegrationTests.java @@ -24,9 +24,11 @@ import org.springframework.cloud.sleuth.test.TestSpanHandler; import org.springframework.context.annotation.Bean; import org.springframework.context.annotation.Configuration; import org.springframework.test.context.ContextConfiguration; +import org.springframework.test.context.TestPropertySource; @SpringBootTest @ContextConfiguration(classes = R2dbcIntegrationTests.Config.class) +@TestPropertySource(properties = "logging.level.org.springframework.cloud=TRACE") public class R2dbcIntegrationTests extends org.springframework.cloud.sleuth.instrument.r2dbc.R2dbcIntegrationTests { @Configuration(proxyBeanMethods = false) diff --git a/tests/common/src/main/java/org/springframework/cloud/sleuth/instrument/r2dbc/R2dbcIntegrationTests.java b/tests/common/src/main/java/org/springframework/cloud/sleuth/instrument/r2dbc/R2dbcIntegrationTests.java index 6a89dae66..30169dc46 100644 --- a/tests/common/src/main/java/org/springframework/cloud/sleuth/instrument/r2dbc/R2dbcIntegrationTests.java +++ b/tests/common/src/main/java/org/springframework/cloud/sleuth/instrument/r2dbc/R2dbcIntegrationTests.java @@ -28,6 +28,7 @@ import org.slf4j.LoggerFactory; import org.springframework.beans.factory.annotation.Autowired; import org.springframework.boot.CommandLineRunner; import org.springframework.boot.autoconfigure.EnableAutoConfiguration; +import org.springframework.cloud.sleuth.Tracer; import org.springframework.cloud.sleuth.exporter.FinishedSpan; import org.springframework.cloud.sleuth.test.TestSpanHandler; import org.springframework.context.annotation.Bean; @@ -46,6 +47,9 @@ public abstract class R2dbcIntegrationTests { @Autowired TestSpanHandler spans; + @Autowired + Tracer tracer; + @Test public void should_pass_tracing_information_when_using_r2dbc() { Set traceIds = this.spans.reportedSpans().stream().map(FinishedSpan::getTraceId) @@ -62,6 +66,8 @@ public abstract class R2dbcIntegrationTests { .collect(Collectors.toList()); then(spanNames.stream().filter("tx"::equalsIgnoreCase).collect(Collectors.toList())).hasSize(2); then(remoteServiceNames.stream().filter("h2"::equalsIgnoreCase).collect(Collectors.toList())).hasSize(9); + // TODO: First fix the SpanAndScope stacking + // then(tracer.currentSpan()).isNull(); } @Configuration(proxyBeanMethods = false)