Avoid multiple HttpUrlConnection span ending on nested calls (#2530)

Author: eyalkoren

CHANGELOG.asciidoc

@@ -32,6 +32,7 @@ endif::[]
 * Fix logging initialization with Security Manager - {pull}2568[#2568]
 * normalize empty `transaction.type` and `span.type` - {pull}2525[#2525]
 * Allowing square brackets within the <<config-capture-jmx-metrics>> config value - {pull}2547[#2547]
+* Fixed duplicated ending of `HttpUrlConnection` spans - {pull}2530[#2530]
 
 
 [[release-notes-1.x]]

apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/AbstractSpan.java

@@ -28,6 +28,7 @@
 import co.elastic.apm.agent.report.ReporterConfiguration;
 import co.elastic.apm.agent.sdk.logging.Logger;
 import co.elastic.apm.agent.sdk.logging.LoggerFactory;
+import co.elastic.apm.agent.util.LoggerUtils;
 
 import javax.annotation.Nullable;
 import java.util.HashMap;
@@ -44,6 +45,8 @@ public abstract class AbstractSpan<T extends AbstractSpan<T>> implements Recycla
     public static final int PRIO_LOW_LEVEL_FRAMEWORK = 10;
     public static final int PRIO_DEFAULT = 0;
     private static final Logger logger = LoggerFactory.getLogger(AbstractSpan.class);
+    private static final Logger oneTimeDuplicatedEndLogger = LoggerUtils.logOnce(logger);
+
     protected static final double MS_IN_MICROS = TimeUnit.MILLISECONDS.toMicros(1);
     protected final TraceContext traceContext;
 
@@ -492,7 +495,12 @@ public final void end(long epochMicros) {
             }
             afterEnd();
         } else {
-            logger.warn("End has already been called: {}", this);
+            if (oneTimeDuplicatedEndLogger.isWarnEnabled()) {
+                oneTimeDuplicatedEndLogger.warn("End has already been called: " + this, new Throwable());
+            } else {
+                logger.warn("End has already been called: {}", this);
+                logger.debug("Consecutive AbstractSpan#end() invocation stack trace: ", new Throwable());
+            }
             assert false;
         }
     }

apm-agent-plugins/apm-urlconnection-plugin/src/main/java/co/elastic/apm/agent/urlconnection/HttpUrlConnectionInstrumentation.java

@@ -25,6 +25,8 @@
 import co.elastic.apm.agent.impl.transaction.Outcome;
 import co.elastic.apm.agent.impl.transaction.Span;
 import co.elastic.apm.agent.impl.transaction.TraceContext;
+import co.elastic.apm.agent.sdk.state.CallDepth;
+import co.elastic.apm.agent.sdk.state.GlobalState;
 import co.elastic.apm.agent.sdk.weakconcurrent.WeakMap;
 import net.bytebuddy.asm.Advice;
 import net.bytebuddy.description.NamedElement;
@@ -45,9 +47,11 @@
 import static net.bytebuddy.matcher.ElementMatchers.not;
 import static net.bytebuddy.matcher.ElementMatchers.takesArguments;
 
+@GlobalState
 public abstract class HttpUrlConnectionInstrumentation extends TracerAwareInstrumentation {
 
-    private static final WeakMap<HttpURLConnection, Span> inFlightSpans = WeakConcurrentProviderImpl.createWeakSpanMap();
+    public static final WeakMap<HttpURLConnection, Span> inFlightSpans = WeakConcurrentProviderImpl.createWeakSpanMap();
+    public static final CallDepth callDepth = CallDepth.get(HttpUrlConnectionInstrumentation.class);
 
     @Override
     public Collection<String> getInstrumentationGroupNames() {
@@ -73,6 +77,7 @@ public static Object enter(@Advice.This HttpURLConnection thiz,
                                        @Advice.FieldValue("connected") boolean connected,
                                        @Advice.Origin String signature) {
 
+                boolean isNestedCall = callDepth.isNestedCallAndIncrement();
                 AbstractSpan<?> parent = tracer.getActive();
                 if (parent == null) {
                     return null;
@@ -89,10 +94,11 @@ public static Object enter(@Advice.This HttpURLConnection thiz,
                         }
                     }
                 }
-                if (span != null) {
+                if (!isNestedCall && span != null) {
                     span.activate();
+                    return span;
                 }
-                return span;
+                return null;
             }
 
             @Advice.OnMethodExit(suppress = Throwable.class, onThrowable = Throwable.class, inline = false)
@@ -102,29 +108,39 @@ public static void exit(@Advice.This HttpURLConnection thiz,
                                     @Advice.Enter @Nullable Object spanObject,
                                     @Advice.Origin String signature) {
 
+                callDepth.decrement();
                 Span span = (Span) spanObject;
                 if (span == null) {
                     return;
                 }
-                span.deactivate();
-                if (responseCode != -1) {
-                    inFlightSpans.remove(thiz);
-                    // if the response code is set, the connection has been established via getOutputStream
-                    // if the response code is unset even after getOutputStream has been called, there will be an exception
-                    span.getContext().getHttp().withStatusCode(responseCode);
-                    span.captureException(t).end();
-                } else if (t != null) {
-                    inFlightSpans.remove(thiz);
-
-                    // an exception here is synonym of failure, for example with circular redirects
-                    span.captureException(t)
-                        .withOutcome(Outcome.FAILURE)
-                        .end();
-                } else {
-                    // if connect or getOutputStream has been called we can't end the span right away
-                    // we have to store associate it with thiz HttpURLConnection instance and end once getInputStream has been called
-                    // note that this could happen on another thread
-                    inFlightSpans.put(thiz, span);
+                try {
+                    if (responseCode != -1) {
+                        inFlightSpans.remove(thiz);
+                        // if the response code is set, the connection has been established via getOutputStream
+                        // if the response code is unset even after getOutputStream has been called, there will be an exception
+                        // checking if "finished" to avoid multiple endings on nested calls
+                        if (!span.isFinished()) {
+                            span.getContext().getHttp().withStatusCode(responseCode);
+                            span.captureException(t).end();
+                        }
+                    } else if (t != null) {
+                        inFlightSpans.remove(thiz);
+
+                        // an exception here is synonym of failure, for example with circular redirects
+                        // checking if "finished" to avoid multiple endings on nested calls
+                        if (!span.isFinished()) {
+                            span.captureException(t)
+                                .withOutcome(Outcome.FAILURE)
+                                .end();
+                        }
+                    } else {
+                        // if connect or getOutputStream has been called we can't end the span right away
+                        // we have to store associate it with thiz HttpURLConnection instance and end once getInputStream has been called
+                        // note that this could happen on another thread
+                        inFlightSpans.put(thiz, span);
+                    }
+                } finally {
+                    span.deactivate();
                 }
             }
         }