This is an automated email from the ASF dual-hosted git repository.
davsclaus pushed a commit to branch main
in repository https://gitbox.apache.org/repos/asf/camel.git
The following commit(s) were added to refs/heads/main by this push:
new 747cdbb3c5c Adding additional logging to scope creation and closing
(#10646)
747cdbb3c5c is described below
commit 747cdbb3c5c4fff7b8e316d206bda3e5d2303202
Author: Marcin Grzejszczak <[email protected]>
AuthorDate: Tue Jul 11 19:12:22 2023 +0200
Adding additional logging to scope creation and closing (#10646)
* 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
* Removes the scope wrapper workaround + allows multiple scope closing
---
.../CamelMicrometerObservationTestSupport.java | 7 ++++
.../src/test/resources/log4j2.properties | 2 +
.../CamelOpenTelemetryTestSupport.java | 7 ++++
.../src/test/resources/log4j2.properties | 2 +
.../apache/camel/tracing/ActiveSpanManager.java | 43 +++++-----------------
.../main/java/org/apache/camel/tracing/Tracer.java | 2 +-
6 files changed, 29 insertions(+), 34 deletions(-)
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..e8f85339941 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=INFO
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..08423f8d76e 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=INFO
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..c6f6b188cab 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
@@ -119,7 +119,10 @@ public final class ActiveSpanManager {
public Holder(Holder parent, SpanAdapter span) {
this.parent = parent;
this.span = span;
- this.scope = new ScopeWrapper(span.makeCurrent(),
Thread.currentThread().getId());
+ this.scope = span.makeCurrent();
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("Tracing: started scope={}", this.scope);
+ }
}
public Holder getParent() {
@@ -131,39 +134,13 @@ public final class ActiveSpanManager {
}
private void closeScope() {
- if (scope != null) {
- try {
- scope.close();
- } catch (Exception e) {
- LOG.debug("Failed to close span scope", e);
+ try {
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("Tracing: closing scope={}", this.scope);
}
- this.scope = null;
- }
- }
- }
-
- /**
- * Makes closing scopes idempotent and prevents restoring scope on the
wrong thread: Should be removed if
- * https://github.com/open-telemetry/opentelemetry-java/issues/5055 is
fixed.
- */
- private static class ScopeWrapper implements AutoCloseable {
- private final long startThreadId;
- private final AutoCloseable inner;
- private boolean closed;
-
- public ScopeWrapper(AutoCloseable inner, long startThreadId) {
- this.startThreadId = startThreadId;
- this.inner = inner;
- }
-
- @Override
- public void close() throws Exception {
- if (!closed && Thread.currentThread().getId() == startThreadId) {
- closed = true;
- inner.close();
- } else {
- LOG.debug("not closing scope, closed - {}, started on thread -
'{}', current thread - '{}'",
- closed, startThreadId, Thread.currentThread().getId());
+ scope.close();
+ } catch (Exception e) {
+ LOG.debug("Failed to close span scope", e);
}
}
}
diff --git
a/components/camel-tracing/src/main/java/org/apache/camel/tracing/Tracer.java
b/components/camel-tracing/src/main/java/org/apache/camel/tracing/Tracer.java
index 7853762fec6..1b9c5297112 100644
---
a/components/camel-tracing/src/main/java/org/apache/camel/tracing/Tracer.java
+++
b/components/camel-tracing/src/main/java/org/apache/camel/tracing/Tracer.java
@@ -273,7 +273,7 @@ public abstract class Tracer extends ServiceSupport
implements RoutePolicyFactor
SpanAdapter span =
ActiveSpanManager.getSpan(ese.getExchange());
if (span != null) {
if (LOG.isTraceEnabled()) {
- LOG.trace("Tracing: start client span={}", span);
+ LOG.trace("Tracing: stop client span={}", span);
}
sd.post(span, ese.getExchange(), ese.getEndpoint());
ActiveSpanManager.deactivate(ese.getExchange());
