fix span stacktrace capture (#3474)

elastic · Jan 8, 2024 · f98c48d · f98c48d
1 parent fa6fed1
commit f98c48d
Show file tree

Hide file tree

Showing 4 changed files with 25 additions and 10 deletions.
diff --git a/CHANGELOG.asciidoc b/CHANGELOG.asciidoc
@@ -34,6 +34,8 @@ Use subheadings with the "=====" level for adding notes for unreleased changes:
 [float]
 ===== Bug fixes
 * Fixed NPE in ApacheHttpClientApiAdapter#getHostName - {pull}3479[#3479]
+* Fix span stack trace when combined with span compression - {pull}3474[#3474]
+
 
 [[release-notes-1.x]]
 === Java Agent version 1.x

diff --git a/apm-agent-core/src/main/java/co/elastic/apm/agent/impl/ElasticApmTracer.java b/apm-agent-core/src/main/java/co/elastic/apm/agent/impl/ElasticApmTracer.java
@@ -107,7 +107,6 @@ public class ElasticApmTracer implements Tracer {
     private static volatile boolean classloaderCheckOk = false;
 
     private final ConfigurationRegistry configurationRegistry;
-    private final StacktraceConfiguration stacktraceConfiguration;
     private final ApmServerClient apmServerClient;
     private final List<LifecycleListener> lifecycleListeners = new CopyOnWriteArrayList<>();
     private final ObjectPool<Transaction> transactionPool;
@@ -203,7 +202,6 @@ private static void checkClassloader() {
         this.metricRegistry = metricRegistry;
         this.configurationRegistry = configurationRegistry;
         this.reporter = reporter;
-        this.stacktraceConfiguration = configurationRegistry.getConfig(StacktraceConfiguration.class);
         this.apmServerClient = apmServerClient;
         this.ephemeralId = ephemeralId;
         this.metaDataFuture = metaDataFuture;
@@ -574,12 +572,6 @@ private void reportSpan(Span span) {
         // makes sure that parents are also non-discardable
         span.setNonDiscardable();
 
-        long spanStackTraceMinDurationMs = stacktraceConfiguration.getSpanStackTraceMinDurationMs();
-        if (spanStackTraceMinDurationMs >= 0 && span.isSampled() && span.getStackFrames() == null) {
-            if (span.getDurationMs() >= spanStackTraceMinDurationMs) {
-                span.withStacktrace(new Throwable());
-            }
-        }
         reporter.report(span);
     }
 

diff --git a/apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/Span.java b/apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/Span.java
@@ -26,6 +26,7 @@
 import co.elastic.apm.agent.impl.context.ServiceTarget;
 import co.elastic.apm.agent.impl.context.SpanContext;
 import co.elastic.apm.agent.impl.context.Url;
+import co.elastic.apm.agent.impl.stacktrace.StacktraceConfiguration;
 import co.elastic.apm.agent.tracer.util.ResultUtil;
 import co.elastic.apm.agent.sdk.logging.Logger;
 import co.elastic.apm.agent.sdk.logging.LoggerFactory;
@@ -43,6 +44,7 @@ public class Span extends AbstractSpan<Span> implements Recyclable, co.elastic.a
     private static final Logger logger = LoggerFactory.getLogger(Span.class);
     public static final long MAX_LOG_INTERVAL_MICRO_SECS = TimeUnit.MINUTES.toMicros(5);
     private static long lastSpanMaxWarningTimestamp;
+    private final StacktraceConfiguration stacktraceConfiguration;
 
     /**
      * A subtype describing this span (eg 'mysql', 'elasticsearch', 'jsf' etc)
@@ -86,6 +88,7 @@ public void setNonDiscardable() {
 
     public Span(ElasticApmTracer tracer) {
         super(tracer);
+        this.stacktraceConfiguration = tracer.getConfig(StacktraceConfiguration.class);
     }
 
     public <T> Span start(TraceContext.ChildContextCreator<T> childContextCreator, T parentContext, Baggage parentBaggage, long epochMicros) {
@@ -263,6 +266,14 @@ public void beforeEnd(long epochMicros) {
 
     @Override
     protected void afterEnd() {
+        // capture stack trace when the span ends, relies on this method being called synchronously from the instrumentation
+        long spanStackTraceMinDurationMs = stacktraceConfiguration.getSpanStackTraceMinDurationMs();
+        if (spanStackTraceMinDurationMs >= 0 && isSampled() && stackFrames == null) {
+            if (getDurationMs() >= spanStackTraceMinDurationMs) {
+                this.stacktrace = new Throwable();
+            }
+        }
+
         // Why do we increment references of this span here?
         // The only thing preventing the "this"-span from being recycled is the initial reference increment in onAfterStart()
         // There are multiple ways in afterEnd() on how this reference may be decremented and therefore potentially causing recycling:

diff --git a/apm-agent-core/src/test/java/co/elastic/apm/agent/impl/ElasticApmTracerTest.java b/apm-agent-core/src/test/java/co/elastic/apm/agent/impl/ElasticApmTracerTest.java
@@ -48,6 +48,7 @@
 import javax.annotation.Nullable;
 import java.io.IOException;
 import java.util.HashMap;
+import java.util.Arrays;
 import java.util.List;
 import java.util.Map;
 import java.util.Objects;
@@ -159,11 +160,20 @@ void testEnableStacktraces() throws InterruptedException {
             Span span = tracerImpl.getActive().createSpan();
             try (Scope spanScope = span.activateInScope()) {
                 Thread.sleep(10);
-                span.end();
+                stackTraceEndSpan(span);
             }
             transaction.end();
         }
-        assertThat(reporter.getFirstSpan().getStacktrace()).isNotNull();
+        Throwable stackTrace = reporter.getFirstSpan().getStacktrace();
+        assertThat(stackTrace).isNotNull();
+        assertThat(Arrays.stream(stackTrace.getStackTrace()).filter(stackTraceElement ->
+            stackTraceElement.getMethodName().equals("stackTraceEndSpan")
+                && stackTraceElement.getClassName().equals(ElasticApmTracerTest.class.getName()))).hasSize(1);
+    }
+
+    private static void stackTraceEndSpan(Span span) {
+        // dummy method used just to verify that the captured stack trace contains it
+        span.end();
     }
 
     @Test