You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@camel.apache.org by da...@apache.org on 2023/07/11 17:12:28 UTC
[camel] branch main updated: Adding additional logging to scope creation and closing (#10646)
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 <mg...@vmware.com>
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());