You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@camel.apache.org by mg...@apache.org on 2023/07/10 14:53:33 UTC
[camel] 01/01: Adding additional logging to scope creation and closing
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 12bf21c5a19d481c3c38086ab70077d16e355536
Author: Marcin Grzejszczak <mg...@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 | 8 ++++++++
.../org/apache/camel/observation/MulticastRouteTest.java | 2 ++
.../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 +++++++++++++
6 files changed, 34 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..bf660230733 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,10 @@ 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.junit.jupiter.api.BeforeEach;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
@@ -87,6 +90,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/java/org/apache/camel/observation/MulticastRouteTest.java b/components/camel-observation/src/test/java/org/apache/camel/observation/MulticastRouteTest.java
index c2ff9f0f1e5..6da95516d4d 100644
--- a/components/camel-observation/src/test/java/org/apache/camel/observation/MulticastRouteTest.java
+++ b/components/camel-observation/src/test/java/org/apache/camel/observation/MulticastRouteTest.java
@@ -17,8 +17,10 @@
package org.apache.camel.observation;
import io.opentelemetry.api.trace.SpanKind;
+import io.opentelemetry.context.Context;
import org.apache.camel.RoutesBuilder;
import org.apache.camel.builder.RouteBuilder;
+import org.assertj.core.api.Assertions;
import org.junit.jupiter.api.Test;
class MulticastRouteTest extends CamelMicrometerObservationTestSupport {
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);
+ }
}
}
}