Make log correlation GA (#742)

felixbarny · web-flow · commit a4f6c1ce8951 · 2019-07-29T10:21:52.000+02:00
- Load the MDC with the application class loader, as opposed to the Thread's context classloader (fixes #720) - Remove span.id MDC entry This causes the most allocations as in contrast to transaction.id and trace.id, the String manifestation can't be reused. Other agents also don't add the span.id so it makes sense to align on that - Docs improvements - Mention slf4j in supported technologies page
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -11,6 +11,9 @@
  * JDBC's `executeBatch` is not traced
  * Drops non-String labels when connected to APM Server < 6.7 to avoid validation errors (#687)
 
+## Breaking changes
+ * The log correlation feature does not add `span.id` to the MDC anymore but only `trace.id` and `transaction.id` (see #742).
+
 # 1.7.0
 
 ## Features
diff --git a/apm-agent-core/src/main/java/co/elastic/apm/agent/impl/ActivationListener.java b/apm-agent-core/src/main/java/co/elastic/apm/agent/impl/ActivationListener.java
@@ -50,7 +50,8 @@ public interface ActivationListener {
      * That's why there is no {@link TraceContextHolder} parameter.
      * </p>
      *
+     * @param deactivatedContext the context which has just been deactivated
      * @throws Throwable if there was an error while calling this method
      */
-    void afterDeactivate() throws Throwable;
+    void afterDeactivate(TraceContextHolder<?> deactivatedContext) throws Throwable;
 }
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
@@ -225,17 +225,19 @@ public boolean isWrappingAllowedOnThread() {
      * @param parent                the parent of the transaction. May be a traceparent header.
      * @param sampler               the {@link Sampler} instance which is responsible for determining the sampling decision if this is a root transaction
      * @param epochMicros           the start timestamp
-     * @param initiatingClassLoader the class loader corresponding to the service which initiated the creation of the transaction
-     *                              Used to determine the service name.
+     * @param initiatingClassLoader the class loader corresponding to the service which initiated the creation of the transaction.
+     *                              Used to determine the service name and to load application-scoped classes like the {@link org.slf4j.MDC},
+     *                              for log correlation.
      * @param <T>                   the type of the parent. {@code String} in case of a traceparent header.
      * @return a transaction which is a child of the provided parent
      */
-    public <T> Transaction startTransaction(TraceContext.ChildContextCreator<T> childContextCreator, @Nullable T parent, Sampler sampler, long epochMicros, @Nullable ClassLoader initiatingClassLoader) {
+    public <T> Transaction startTransaction(TraceContext.ChildContextCreator<T> childContextCreator, @Nullable T parent, Sampler sampler,
+                                            long epochMicros, @Nullable ClassLoader initiatingClassLoader) {
         Transaction transaction;
         if (!coreConfiguration.isActive()) {
             transaction = noopTransaction();
         } else {
-            transaction = createTransaction().start(childContextCreator, parent, epochMicros, sampler);
+            transaction = createTransaction().start(childContextCreator, parent, epochMicros, sampler, initiatingClassLoader);
         }
         if (logger.isDebugEnabled()) {
             logger.debug("startTransaction {} {", transaction);
diff --git a/apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/TraceContext.java b/apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/TraceContext.java
@@ -27,10 +27,12 @@
 import co.elastic.apm.agent.impl.ElasticApmTracer;
 import co.elastic.apm.agent.impl.sampling.Sampler;
 import co.elastic.apm.agent.util.HexUtils;
+import com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
 import javax.annotation.Nullable;
+import java.lang.ref.WeakReference;
 import java.util.concurrent.Callable;
 
 /**
@@ -56,6 +58,10 @@ public class TraceContext extends TraceContextHolder {
     private static final int PARENT_ID_OFFSET = 36;
     private static final int FLAGS_OFFSET = 53;
     private static final Logger logger = LoggerFactory.getLogger(TraceContext.class);
+    /**
+     * Helps to reduce allocations by caching {@link WeakReference}s to {@link ClassLoader}s
+     */
+    private static final WeakConcurrentMap<ClassLoader, WeakReference<ClassLoader>> classLoaderWeakReferenceCache = new WeakConcurrentMap.WithInlinedExpunction<>();
     private static final ChildContextCreator<TraceContextHolder<?>> FROM_PARENT = new ChildContextCreator<TraceContextHolder<?>>() {
         @Override
         public boolean asChildOf(TraceContext child, TraceContextHolder<?> parent) {
@@ -101,6 +107,9 @@ public boolean asChildOf(TraceContext child, Object ignore) {
     private final StringBuilder outgoingHeader = new StringBuilder(TRACE_PARENT_LENGTH);
     private byte flags;
     private boolean discard;
+    // weakly referencing to avoid CL leaks in case of leaked spans
+    @Nullable
+    private WeakReference<ClassLoader> applicationClassLoader;
 
     /**
      * Avoids clock drifts within a transaction.
@@ -227,6 +236,7 @@ public void asChildOf(TraceContext parent) {
         id.setToRandomValue();
         clock.init(parent.clock);
         serviceName = parent.serviceName;
+        applicationClassLoader = parent.applicationClassLoader;
         onMutation();
     }
 
@@ -246,6 +256,7 @@ public void resetState() {
         discard = false;
         clock.resetState();
         serviceName = null;
+        applicationClassLoader = null;
     }
 
     /**
@@ -362,6 +373,7 @@ public void copyFrom(TraceContext other) {
         discard = other.discard;
         clock.init(other.clock);
         serviceName = other.serviceName;
+        applicationClassLoader = other.applicationClassLoader;
         onMutation();
     }
 
@@ -407,6 +419,26 @@ public Span createSpan(long epochMicros) {
         return tracer.startSpan(fromParent(), this, epochMicros);
     }
 
+    void setApplicationClassLoader(@Nullable ClassLoader classLoader) {
+        if (classLoader != null) {
+            WeakReference<ClassLoader> local = classLoaderWeakReferenceCache.get(classLoader);
+            if (local == null) {
+                local = new WeakReference<>(classLoader);
+                classLoaderWeakReferenceCache.putIfAbsent(classLoader, local);
+            }
+            applicationClassLoader = local;
+        }
+    }
+
+    @Nullable
+    public ClassLoader getApplicationClassLoader() {
+        if (applicationClassLoader != null) {
+            return applicationClassLoader.get();
+        } else {
+            return null;
+        }
+    }
+
     public interface ChildContextCreator<T> {
         boolean asChildOf(TraceContext child, T parent);
     }
diff --git a/apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/TraceContextHolder.java b/apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/TraceContextHolder.java
@@ -113,7 +113,8 @@ public T deactivate() {
         List<ActivationListener> activationListeners = tracer.getActivationListeners();
         for (int i = 0; i < activationListeners.size(); i++) {
             try {
-                activationListeners.get(i).afterDeactivate();
+                // `this` is guaranteed to not be recycled yet as the reference count is only decremented after this method has executed
+                activationListeners.get(i).afterDeactivate(this);
             } catch (Error e) {
                 throw e;
             } catch (Throwable t) {
diff --git a/apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/Transaction.java b/apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/Transaction.java
@@ -94,7 +94,9 @@ public Transaction(ElasticApmTracer tracer) {
         super(tracer);
     }
 
-    public <T> Transaction start(TraceContext.ChildContextCreator<T> childContextCreator, @Nullable T parent, long epochMicros, Sampler sampler) {
+    public <T> Transaction start(TraceContext.ChildContextCreator<T> childContextCreator, @Nullable T parent, long epochMicros,
+                                 Sampler sampler, @Nullable ClassLoader initiatingClassLoader) {
+        traceContext.setApplicationClassLoader(initiatingClassLoader);
         if (parent == null || !childContextCreator.asChildOf(traceContext, parent)) {
             traceContext.asRootSpan(sampler);
         }
diff --git a/apm-agent-core/src/main/java/co/elastic/apm/agent/logging/LoggingConfiguration.java b/apm-agent-core/src/main/java/co/elastic/apm/agent/logging/LoggingConfiguration.java
@@ -100,17 +100,16 @@ public void onChange(ConfigurationOption<?> configurationOption, Level oldValue,
     private final ConfigurationOption<Boolean> logCorrelationEnabled = ConfigurationOption.booleanOption()
         .key("enable_log_correlation")
         .configurationCategory(LOGGING_CATEGORY)
-        .description("A boolean specifying if the agent should integrate into SLF4J's MDC to enable trace-log correlation.\n" +
-            "If set to `true`, the agent will set the `spanId` and `traceId` for the currently active spans and transactions to the MDC.\n" +
+        .description("A boolean specifying if the agent should integrate into SLF4J's https://www.slf4j.org/api/org/slf4j/MDC.html[MDC] to enable trace-log correlation.\n" +
+            "If set to `true`, the agent will set the `trace.id` and `transaction.id` for the currently active spans and transactions to the MDC.\n" +
             "You can then use the pattern format of your logging implementation to write the MDC values to your log file.\n" +
+            "If you are using logback or log4j, add `%X` to the format to log all MDC values or `%X{trace.id}` to only log the trace id.\n" +
             "With the help of Filebeat and Logstash or an Elasticsearch ingest pipeline,\n" +
             "you can index your log files and correlate them with APM traces.\n" +
             "With this integration you can get all logs belonging to a particular trace and vice-versa:\n" +
             "for a specific log, see in which context it has been logged and which parameters the user provided. " +
             "\n" +
-            "While it's allowed to enable this setting at runtime, you can't disable it without a restart.\n" +
-            "\n" +
-            "NOTE: This is an incubating feature and the MDC key names might change.")
+            "While it's allowed to enable this setting at runtime, you can't disable it without a restart.")
         .dynamic(true)
         .addValidator(new ConfigurationOption.Validator<Boolean>() {
             @Override
diff --git a/apm-agent-core/src/test/java/co/elastic/apm/agent/TransactionUtils.java b/apm-agent-core/src/test/java/co/elastic/apm/agent/TransactionUtils.java
@@ -37,7 +37,7 @@
 public class TransactionUtils {
 
     public static void fillTransaction(Transaction t) {
-        t.start(TraceContext.asRoot(), null, (long) 0, ConstantSampler.of(true));
+        t.start(TraceContext.asRoot(), null, (long) 0, ConstantSampler.of(true), TransactionUtils.class.getClassLoader());
         t.setName("GET /api/types");
         t.withType("request");
         t.withResult("success");
diff --git a/apm-agent-core/src/test/java/co/elastic/apm/agent/impl/payload/TransactionPayloadJsonSchemaTest.java b/apm-agent-core/src/test/java/co/elastic/apm/agent/impl/payload/TransactionPayloadJsonSchemaTest.java
@@ -26,7 +26,6 @@
 
 import co.elastic.apm.agent.MockTracer;
 import co.elastic.apm.agent.TransactionUtils;
-import co.elastic.apm.agent.impl.ElasticApmTracer;
 import co.elastic.apm.agent.impl.sampling.ConstantSampler;
 import co.elastic.apm.agent.impl.stacktrace.StacktraceConfiguration;
 import co.elastic.apm.agent.impl.transaction.Span;
@@ -81,7 +80,7 @@ private TransactionPayload createPayloadWithRequiredValues() {
 
     private Transaction createTransactionWithRequiredValues() {
         Transaction t = new Transaction(MockTracer.create());
-        t.start(TraceContext.asRoot(), null, (long) 0, ConstantSampler.of(true));
+        t.start(TraceContext.asRoot(), null, (long) 0, ConstantSampler.of(true), getClass().getClassLoader());
         t.withType("type");
         t.getContext().getRequest().withMethod("GET");
         t.getContext().getRequest().getUrl().appendToFull("http://localhost:8080/foo/bar");
diff --git a/apm-agent-plugins/apm-opentracing-plugin/src/main/java/co/elastic/apm/agent/opentracing/impl/ApmSpanBuilderInstrumentation.java b/apm-agent-plugins/apm-opentracing-plugin/src/main/java/co/elastic/apm/agent/opentracing/impl/ApmSpanBuilderInstrumentation.java
@@ -71,25 +71,25 @@ public CreateSpanInstrumentation() {
         }
 
         @Advice.OnMethodExit(suppress = Throwable.class)
-        public static void createSpan(@Advice.Argument(value = 0, typing = Assigner.Typing.DYNAMIC)
-                                      @Nullable TraceContext parentContext,
+        public static void createSpan(@Advice.Argument(value = 0, typing = Assigner.Typing.DYNAMIC) @Nullable TraceContext parentContext,
+                                      @Advice.Origin Class<?> spanBuilderClass,
                                       @Advice.FieldValue(value = "tags") Map<String, Object> tags,
                                       @Advice.FieldValue(value = "operationName") String operationName,
                                       @Advice.FieldValue(value = "microseconds") long microseconds,
                                       @Advice.Argument(1) @Nullable Iterable<Map.Entry<String, String>> baggage,
                                       @Advice.Return(readOnly = false) Object span) {
-            span = doCreateTransactionOrSpan(parentContext, tags, operationName, microseconds, baggage);
+            span = doCreateTransactionOrSpan(parentContext, tags, operationName, microseconds, baggage, spanBuilderClass.getClassLoader());
         }
 
         @Nullable
         @VisibleForAdvice
         public static AbstractSpan<?> doCreateTransactionOrSpan(@Nullable TraceContext parentContext,
                                                                 Map<String, Object> tags,
                                                                 String operationName, long microseconds,
-                                                                @Nullable Iterable<Map.Entry<String, String>> baggage) {
+                                                                @Nullable Iterable<Map.Entry<String, String>> baggage, ClassLoader applicationClassLoader) {
             if (tracer != null) {
                 if (parentContext == null) {
-                    return createTransaction(tags, operationName, microseconds, baggage, tracer, TraceContext.class.getClassLoader());
+                    return createTransaction(tags, operationName, microseconds, baggage, tracer, applicationClassLoader);
                 } else {
                     if (microseconds >= 0) {
                         return tracer.startSpan(TraceContext.fromParent(), parentContext, microseconds);
diff --git a/apm-agent-plugins/apm-slf4j-plugin/src/main/java/co/elastic/apm/agent/slf4j/Slf4JMdcActivationListener.java b/apm-agent-plugins/apm-slf4j-plugin/src/main/java/co/elastic/apm/agent/slf4j/Slf4JMdcActivationListener.java
@@ -44,7 +44,6 @@ public class Slf4JMdcActivationListener implements ActivationListener {
     // the toString prevents constant folding, which would also make the shade plugin relocate
     private static final String ORG_SLF4J_MDC = "org." + "slf4j.MDC".toString();
     private static final String TRACE_ID = "trace.id";
-    private static final String SPAN_ID = "span.id";
     private static final String TRANSACTION_ID = "transaction.id";
     private static final Logger logger = LoggerFactory.getLogger(Slf4JMdcActivationListener.class);
 
@@ -90,12 +89,10 @@ public Slf4JMdcActivationListener(ElasticApmTracer tracer) {
     @Override
     public void beforeActivate(TraceContextHolder<?> context) throws Throwable {
         if (config.isLogCorrelationEnabled()) {
-            ClassLoader contextClassLoader = getContextClassLoader();
 
-            MethodHandle put = mdcPutMethodHandleCache.get(contextClassLoader);
+            MethodHandle put = mdcPutMethodHandleCache.get(getApplicationClassLoader(context));
             if (put != null && put != NOOP) {
                 TraceContext traceContext = context.getTraceContext();
-                put.invokeExact(SPAN_ID, traceContext.getId().toString());
                 if (tracer.getActive() == null) {
                     put.invokeExact(TRACE_ID, traceContext.getTraceId().toString());
                     put.invokeExact(TRANSACTION_ID, traceContext.getTransactionId().toString());
@@ -105,32 +102,39 @@ public void beforeActivate(TraceContextHolder<?> context) throws Throwable {
     }
 
     @Override
-    public void afterDeactivate() throws Throwable {
+    public void afterDeactivate(TraceContextHolder<?> deactivatedContext) throws Throwable {
         if (config.isLogCorrelationEnabled()) {
 
-            ClassLoader contextClassLoader = getContextClassLoader();
-            TraceContextHolder active = tracer.getActive();
-
-            MethodHandle remove = mdcRemoveMethodHandleCache.get(contextClassLoader);
+            MethodHandle remove = mdcRemoveMethodHandleCache.get(getApplicationClassLoader(deactivatedContext));
             if (remove != null && remove != NOOP) {
-                if (active == null) {
-                    remove.invokeExact(SPAN_ID);
+                if (tracer.getActive() == null) {
                     remove.invokeExact(TRACE_ID);
                     remove.invokeExact(TRANSACTION_ID);
                 }
             }
+        }
+    }
 
-            if (active != null) {
-                MethodHandle put = mdcPutMethodHandleCache.get(contextClassLoader);
-                if (put != null && put != NOOP) {
-                    put.invokeExact(SPAN_ID, active.getTraceContext().getId().toString());
-                }
-            }
+    /**
+     * Looks up the class loader which corresponds to the application the current transaction belongs to.
+     * @param context
+     * @return
+     */
+    private ClassLoader getApplicationClassLoader(TraceContextHolder<?> context) {
+        ClassLoader applicationClassLoader = context.getTraceContext().getApplicationClassLoader();
+        if (applicationClassLoader != null) {
+            return applicationClassLoader;
+        } else {
+            return getFallbackClassLoader();
         }
     }
 
-    private ClassLoader getContextClassLoader() {
-        ClassLoader contextClassLoader = Thread.currentThread().getContextClassLoader();
-        return (contextClassLoader != null) ? contextClassLoader : ClassLoader.getSystemClassLoader();
+    private ClassLoader getFallbackClassLoader() {
+        ClassLoader classLoader = Thread.currentThread().getContextClassLoader();
+        if (classLoader == null) {
+            classLoader =  ClassLoader.getSystemClassLoader();
+        }
+        return classLoader;
     }
+
 }
diff --git a/apm-agent-plugins/apm-slf4j-plugin/src/test/java/co/elastic/apm/agent/slf4j/Slf4JMdcActivationListenerTest.java b/apm-agent-plugins/apm-slf4j-plugin/src/test/java/co/elastic/apm/agent/slf4j/Slf4JMdcActivationListenerTest.java
diff --git a/docs/configuration.asciidoc b/docs/configuration.asciidoc
diff --git a/docs/supported-technologies.asciidoc b/docs/supported-technologies.asciidoc

Original file line number	Diff line number	Diff line change
`@@ -50,7 +50,8 @@ public interface ActivationListener {`
`50`	`50`	`* That's why there is no {@link TraceContextHolder} parameter.`
`51`	`51`	`* </p>`
`52`	`52`	`*`
	`53`	`+ * @param deactivatedContext the context which has just been deactivated`
`53`	`54`	`* @throws Throwable if there was an error while calling this method`
`54`	`55`	`*/`
`55`		`- void afterDeactivate() throws Throwable;`
	`56`	`+ void afterDeactivate(TraceContextHolder<?> deactivatedContext) throws Throwable;`
`56`	`57`	`}`
Original file line number	Diff line number	Diff line change
`@@ -94,7 +94,9 @@ public Transaction(ElasticApmTracer tracer) {`
`94`	`94`	`super(tracer);`
`95`	`95`	`}`
`96`	`96`
`97`		`- public <T> Transaction start(TraceContext.ChildContextCreator<T> childContextCreator, @Nullable T parent, long epochMicros, Sampler sampler) {`
	`97`	`+ public <T> Transaction start(TraceContext.ChildContextCreator<T> childContextCreator, @Nullable T parent, long epochMicros,`
	`98`	`+ Sampler sampler, @Nullable ClassLoader initiatingClassLoader) {`
	`99`	`+ traceContext.setApplicationClassLoader(initiatingClassLoader);`
`98`	`100`	`if (parent == null \|\| !childContextCreator.asChildOf(traceContext, parent)) {`
`99`	`101`	`traceContext.asRootSpan(sampler);`
`100`	`102`	`}`