Adding trace-level log info to HTTP spans (#1425)

Author: eyalkoren

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

@@ -539,6 +539,7 @@ <C> void propagateTraceContext(C carrier, TextHeaderSetter<C> headerSetter) {
             String tracestateHeaderValue = TextTracestateAppender.instance().join(tracestate, coreConfiguration.getTracestateSizeLimit());
             headerSetter.setHeader(TRACESTATE_HEADER_NAME, tracestateHeaderValue, carrier);
         }
+        logger.trace("Trace context headers added to {}", carrier);
     }
 
     /**

apm-agent-plugins/apm-httpclient-core/src/main/java/co/elastic/apm/agent/http/client/HttpClientHelper.java

@@ -28,11 +28,16 @@
 import co.elastic.apm.agent.impl.context.Destination;
 import co.elastic.apm.agent.impl.transaction.AbstractSpan;
 import co.elastic.apm.agent.impl.transaction.Span;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 import javax.annotation.Nullable;
 import java.net.URI;
 
 public class HttpClientHelper {
+
+    private static final Logger logger = LoggerFactory.getLogger(HttpClientHelper.class);
+
     public static final String EXTERNAL_TYPE = "external";
     public static final String HTTP_SUBTYPE = "http";
 
@@ -68,6 +73,9 @@ public static Span startHttpClientSpan(AbstractSpan<?> parent, String method, @N
             }
             setDestinationServiceDetails(span, scheme, hostName, port);
         }
+        if (logger.isTraceEnabled()) {
+            logger.trace("Created an HTTP exit span: {} for URI: {}. Parent span: {}", span, uri, parent);
+        }
         return span;
     }
 

apm-agent-plugins/apm-spring-resttemplate-plugin/src/main/java/co/elastic/apm/agent/resttemplate/SpringRestTemplateAdvice.java

@@ -0,0 +1,56 @@
+package co.elastic.apm.agent.resttemplate;
+
+import co.elastic.apm.agent.bci.TracerAwareInstrumentation;
+import co.elastic.apm.agent.http.client.HttpClientHelper;
+import co.elastic.apm.agent.impl.transaction.AbstractSpan;
+import co.elastic.apm.agent.impl.transaction.Span;
+import net.bytebuddy.asm.Advice;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+import org.springframework.http.client.ClientHttpRequest;
+import org.springframework.http.client.ClientHttpResponse;
+
+import javax.annotation.Nullable;
+import java.io.IOException;
+import java.util.Objects;
+
+public class SpringRestTemplateAdvice {
+
+    private static final Logger logger = LoggerFactory.getLogger(SpringRestTemplateAdvice.class);
+
+    @Nullable
+    @Advice.OnMethodEnter(suppress = Throwable.class, inline = false)
+    public static Object beforeExecute(@Advice.This ClientHttpRequest request) {
+        logger.trace("Enter advice for method {}#execute()", request.getClass().getName());
+        if (TracerAwareInstrumentation.tracer.getActive() == null) {
+            return null;
+        }
+        final AbstractSpan<?> parent = TracerAwareInstrumentation.tracer.getActive();
+        Span span = HttpClientHelper.startHttpClientSpan(parent, Objects.toString(request.getMethod()), request.getURI(), request.getURI().getHost());
+        if (span != null) {
+            span.activate();
+            span.propagateTraceContext(request, SpringRestRequestHeaderSetter.INSTANCE);
+            return span;
+        }
+        return null;
+    }
+
+    @Advice.OnMethodExit(suppress = Throwable.class, onThrowable = Throwable.class, inline = false)
+    public static void afterExecute(@Advice.Return @Nullable ClientHttpResponse clientHttpResponse,
+                                    @Advice.Enter @Nullable Object spanObj,
+                                    @Advice.Thrown @Nullable Throwable t) throws IOException {
+        logger.trace("Exit advice for RestTemplate client execute() method, span object: {}", spanObj);
+        if (spanObj instanceof Span) {
+            Span span = (Span) spanObj;
+            try {
+                if (clientHttpResponse != null) {
+                    int statusCode = clientHttpResponse.getRawStatusCode();
+                    span.getContext().getHttp().withStatusCode(statusCode);
+                }
+                span.captureException(t);
+            } finally {
+                span.deactivate().end();
+            }
+        }
+    }
+}

apm-agent-plugins/apm-spring-resttemplate-plugin/src/main/java/co/elastic/apm/agent/resttemplate/SpringRestTemplateInstrumentation.java

@@ -25,21 +25,12 @@
 package co.elastic.apm.agent.resttemplate;
 
 import co.elastic.apm.agent.bci.TracerAwareInstrumentation;
-import co.elastic.apm.agent.http.client.HttpClientHelper;
-import co.elastic.apm.agent.impl.transaction.AbstractSpan;
-import co.elastic.apm.agent.impl.transaction.Span;
-import net.bytebuddy.asm.Advice;
 import net.bytebuddy.description.method.MethodDescription;
 import net.bytebuddy.description.type.TypeDescription;
 import net.bytebuddy.matcher.ElementMatcher;
-import org.springframework.http.client.ClientHttpRequest;
-import org.springframework.http.client.ClientHttpResponse;
 
-import javax.annotation.Nullable;
-import java.io.IOException;
 import java.util.Arrays;
 import java.util.Collection;
-import java.util.Objects;
 
 import static net.bytebuddy.matcher.ElementMatchers.declaresMethod;
 import static net.bytebuddy.matcher.ElementMatchers.hasSuperType;
@@ -77,40 +68,4 @@ public Class<?> getAdviceClass() {
     public Collection<String> getInstrumentationGroupNames() {
         return Arrays.asList("http-client", "spring-resttemplate");
     }
-
-    public static class SpringRestTemplateAdvice {
-        @Nullable
-        @Advice.OnMethodEnter(suppress = Throwable.class, inline = false)
-        public static Object beforeExecute(@Advice.This ClientHttpRequest request) {
-            if (tracer.getActive() == null) {
-                return null;
-            }
-            final AbstractSpan<?> parent = tracer.getActive();
-            Span span = HttpClientHelper.startHttpClientSpan(parent, Objects.toString(request.getMethod()), request.getURI(), request.getURI().getHost());
-            if (span != null) {
-                span.activate();
-                span.propagateTraceContext(request, SpringRestRequestHeaderSetter.INSTANCE);
-                return span;
-            }
-            return null;
-        }
-
-        @Advice.OnMethodExit(suppress = Throwable.class, onThrowable = Throwable.class, inline = false)
-        public static void afterExecute(@Advice.Return @Nullable ClientHttpResponse clientHttpResponse,
-                                        @Advice.Enter @Nullable Object spanObj,
-                                        @Advice.Thrown @Nullable Throwable t) throws IOException {
-            if (spanObj instanceof Span) {
-                Span span = (Span) spanObj;
-                try {
-                    if (clientHttpResponse != null) {
-                        int statusCode = clientHttpResponse.getRawStatusCode();
-                        span.getContext().getHttp().withStatusCode(statusCode);
-                    }
-                    span.captureException(t);
-                } finally {
-                    span.deactivate().end();
-                }
-            }
-        }
-    }
 }