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);
+ }
}
}
}
