This is an automated email from the ASF dual-hosted git repository. mgrzejszczak pushed a commit to branch tryingToFixLeak in repository https://gitbox.apache.org/repos/asf/camel.git
commit 88889b008a021b5d9f5c6d7d0bf632eff3443461 Author: Marcin Grzejszczak <mgrzejszc...@vmware.com> AuthorDate: Mon Jul 10 16:50:59 2023 +0200 Adding additional logging to scope creation and closing the problem we have is that one of the spans in one of the tests (most probably MulticastRouteTest) is not being closed and the span is left in the test thread. Due to this other tests are failing. This commit adds a after test check that there is no leaking span (for OTel and Micrometer Observation modules). Also it adds some additional logging on trace level that will store the stacktrace of each scope and when on close the scope is trying to get closed in a wrong thread we can recreate where it was created and where it's being closed. related to pr gh-10539 --- .../observation/CamelMicrometerObservationTestSupport.java | 7 +++++++ .../camel-observation/src/test/resources/log4j2.properties | 2 ++ .../camel/opentelemetry/CamelOpenTelemetryTestSupport.java | 7 +++++++ .../src/test/resources/log4j2.properties | 2 ++ .../java/org/apache/camel/tracing/ActiveSpanManager.java | 13 +++++++++++++ 5 files changed, 31 insertions(+) diff --git a/components/camel-observation/src/test/java/org/apache/camel/observation/CamelMicrometerObservationTestSupport.java b/components/camel-observation/src/test/java/org/apache/camel/observation/CamelMicrometerObservationTestSupport.java index 4022b6f186a..bc05d15ad1e 100644 --- a/components/camel-observation/src/test/java/org/apache/camel/observation/CamelMicrometerObservationTestSupport.java +++ b/components/camel-observation/src/test/java/org/apache/camel/observation/CamelMicrometerObservationTestSupport.java @@ -57,7 +57,9 @@ import io.opentelemetry.sdk.trace.export.SimpleSpanProcessor; import org.apache.camel.CamelContext; import org.apache.camel.test.junit5.CamelTestSupport; import org.apache.camel.tracing.SpanDecorator; +import org.assertj.core.api.Assertions; import org.awaitility.Awaitility; +import org.junit.jupiter.api.AfterEach; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -87,6 +89,11 @@ class CamelMicrometerObservationTestSupport extends CamelTestSupport { this.expected = expected; } + @AfterEach + void noLeakingContext() { + Assertions.assertThat(Context.current()).as("There must be no leaking span after test").isSameAs(Context.root()); + } + @Override protected CamelContext createCamelContext() throws Exception { CamelContext context = super.createCamelContext(); diff --git a/components/camel-observation/src/test/resources/log4j2.properties b/components/camel-observation/src/test/resources/log4j2.properties index f54d01bb554..af1e7f203ab 100644 --- a/components/camel-observation/src/test/resources/log4j2.properties +++ b/components/camel-observation/src/test/resources/log4j2.properties @@ -25,5 +25,7 @@ appender.out.layout.type=PatternLayout appender.out.layout.pattern=%d [%-15.15t] %-5p %-30.30c{1} - %m%n logger.opentelemetry.name=org.apache.camel.observation logger.opentelemetry.level=INFO +logger.tracing.name=org.apache.camel.tracing +logger.tracing.level=TRACE rootLogger.level=INFO rootLogger.appenderRef.file.ref=file diff --git a/components/camel-opentelemetry/src/test/java/org/apache/camel/opentelemetry/CamelOpenTelemetryTestSupport.java b/components/camel-opentelemetry/src/test/java/org/apache/camel/opentelemetry/CamelOpenTelemetryTestSupport.java index 9555e747dd2..8c8bbf8d867 100644 --- a/components/camel-opentelemetry/src/test/java/org/apache/camel/opentelemetry/CamelOpenTelemetryTestSupport.java +++ b/components/camel-opentelemetry/src/test/java/org/apache/camel/opentelemetry/CamelOpenTelemetryTestSupport.java @@ -41,6 +41,8 @@ import org.apache.camel.CamelContext; import org.apache.camel.test.junit5.CamelTestSupport; import org.apache.camel.tracing.SpanDecorator; import org.awaitility.Awaitility; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.Assertions; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -66,6 +68,11 @@ class CamelOpenTelemetryTestSupport extends CamelTestSupport { this.expected = expected; } + @AfterEach + void noLeakingContext() { + Assertions.assertSame(Context.root(), Context.current(), "There must be no leaking span after test"); + } + @Override protected CamelContext createCamelContext() throws Exception { CamelContext context = super.createCamelContext(); diff --git a/components/camel-opentelemetry/src/test/resources/log4j2.properties b/components/camel-opentelemetry/src/test/resources/log4j2.properties index 89ff53a8dd5..7db0d5df3cb 100644 --- a/components/camel-opentelemetry/src/test/resources/log4j2.properties +++ b/components/camel-opentelemetry/src/test/resources/log4j2.properties @@ -25,5 +25,7 @@ appender.out.layout.type=PatternLayout appender.out.layout.pattern=%d [%-15.15t] %-5p %-30.30c{1} - %m%n logger.opentelemetry.name=org.apache.camel.opentelemetry logger.opentelemetry.level=INFO +logger.tracing.name=org.apache.camel.tracing +logger.tracing.level=TRACE rootLogger.level=INFO rootLogger.appenderRef.file.ref=file diff --git a/components/camel-tracing/src/main/java/org/apache/camel/tracing/ActiveSpanManager.java b/components/camel-tracing/src/main/java/org/apache/camel/tracing/ActiveSpanManager.java index b9c502a49f0..392d9880f9c 100644 --- a/components/camel-tracing/src/main/java/org/apache/camel/tracing/ActiveSpanManager.java +++ b/components/camel-tracing/src/main/java/org/apache/camel/tracing/ActiveSpanManager.java @@ -151,19 +151,32 @@ public final class ActiveSpanManager { private final AutoCloseable inner; private boolean closed; + private Throwable exceptionForStacktrace; + public ScopeWrapper(AutoCloseable inner, long startThreadId) { this.startThreadId = startThreadId; this.inner = inner; + if (LOG.isTraceEnabled()) { + LOG.trace("Created scope {}", inner); + this.exceptionForStacktrace = new RuntimeException("To see where this scope got created"); + } } @Override public void close() throws Exception { if (!closed && Thread.currentThread().getId() == startThreadId) { closed = true; + if (LOG.isTraceEnabled()) { + LOG.trace("Closing scope {}", inner); + } inner.close(); } else { LOG.debug("not closing scope, closed - {}, started on thread - '{}', current thread - '{}'", closed, startThreadId, Thread.currentThread().getId()); + if (LOG.isTraceEnabled() && this.exceptionForStacktrace != null) { + LOG.trace("Stacktrace of where we are", new RuntimeException()); + LOG.trace("Stacktrace of where the scope was created", this.exceptionForStacktrace); + } } } }