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 index 6639ca6115..b51d8402ec 100644 --- 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 @@ -30,6 +30,8 @@ import co.elastic.apm.agent.impl.transaction.TraceContext; import co.elastic.apm.agent.impl.transaction.TraceContextHolder; import co.elastic.apm.agent.logging.LoggingConfiguration; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import javax.annotation.Nullable; import java.lang.invoke.MethodHandle; @@ -44,6 +46,10 @@ public class Slf4JMdcActivationListener implements ActivationListener { 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); + + // Never invoked- only used for caching ClassLoaders that can't load the slf4j MDC class + private static final MethodHandle NOOP = MethodHandles.constant(String.class, "ClassLoader cannot load slf4j API"); private final WeakKeySoftValueLoadingCache mdcPutMethodHandleCache = new WeakKeySoftValueLoadingCache<>(new WeakKeySoftValueLoadingCache.ValueSupplier() { @@ -53,9 +59,9 @@ public MethodHandle get(ClassLoader classLoader) { try { return MethodHandles.lookup() .findStatic(classLoader.loadClass(ORG_SLF4J_MDC), "put", MethodType.methodType(void.class, String.class, String.class)); - } catch (Exception ignore) { - // this class loader does not have the slf4j api - return null; + } catch (Exception e) { + logger.warn("Class loader " + classLoader + " cannot load slf4j API", e); + return NOOP; } } }); @@ -68,8 +74,8 @@ public MethodHandle get(ClassLoader classLoader) { return MethodHandles.lookup() .findStatic(classLoader.loadClass(ORG_SLF4J_MDC), "remove", MethodType.methodType(void.class, String.class)); } catch (Exception ignore) { - // this class loader does not have the slf4j api - return null; + // No need to log - logged already when populated the put cache + return NOOP; } } }); @@ -84,10 +90,10 @@ public Slf4JMdcActivationListener(ElasticApmTracer tracer) { @Override public void beforeActivate(TraceContextHolder context) throws Throwable { if (config.isLogCorrelationEnabled()) { - ClassLoader contextClassLoader = Thread.currentThread().getContextClassLoader(); + ClassLoader contextClassLoader = getContextClassLoader(); MethodHandle put = mdcPutMethodHandleCache.get(contextClassLoader); - if (put != null) { + if (put != null && put != NOOP) { TraceContext traceContext = context.getTraceContext(); put.invokeExact(SPAN_ID, traceContext.getId().toString()); if (tracer.getActive() == null) { @@ -102,11 +108,11 @@ public void beforeActivate(TraceContextHolder context) throws Throwable { public void afterDeactivate() throws Throwable { if (config.isLogCorrelationEnabled()) { - ClassLoader contextClassLoader = Thread.currentThread().getContextClassLoader(); + ClassLoader contextClassLoader = getContextClassLoader(); TraceContextHolder active = tracer.getActive(); MethodHandle remove = mdcRemoveMethodHandleCache.get(contextClassLoader); - if (remove != null) { + if (remove != null && remove != NOOP) { if (active == null) { remove.invokeExact(SPAN_ID); remove.invokeExact(TRACE_ID); @@ -116,10 +122,15 @@ public void afterDeactivate() throws Throwable { if (active != null) { MethodHandle put = mdcPutMethodHandleCache.get(contextClassLoader); - if (put != null) { + if (put != null && put != NOOP) { put.invokeExact(SPAN_ID, active.getTraceContext().getId().toString()); } } } } + + private ClassLoader getContextClassLoader() { + ClassLoader contextClassLoader = Thread.currentThread().getContextClassLoader(); + return (contextClassLoader != null) ? contextClassLoader : ClassLoader.getSystemClassLoader(); + } } 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 index 12acf43f7c..a2d2800198 100644 --- 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 @@ -37,6 +37,8 @@ import org.slf4j.MDC; import java.io.IOException; +import java.util.concurrent.CompletableFuture; +import java.util.concurrent.TimeUnit; import static org.assertj.core.api.Assertions.assertThat; import static org.assertj.core.api.Assertions.assertThatCode; @@ -79,14 +81,60 @@ void testMdcIntegrationTransactionScopeInDifferentThread() throws Exception { when(loggingConfiguration.isLogCorrelationEnabled()).thenReturn(true); Transaction transaction = tracer.startTransaction(TraceContext.asRoot(), null, null).withType("request").withName("test"); assertMdcIsEmpty(); + final CompletableFuture result = new CompletableFuture<>(); Thread thread = new Thread(() -> { assertMdcIsEmpty(); try (Scope scope = transaction.activateInScope()) { assertMdcIsSet(transaction); } assertMdcIsEmpty(); + result.complete(true); }); thread.start(); + assertThat(result.get(1000, TimeUnit.MILLISECONDS).booleanValue()).isTrue(); + assertMdcIsEmpty(); + thread.join(); + transaction.end(); + } + + @Test + void testNoopWhenClassLoaderCantLoadMdc() throws Exception { + when(loggingConfiguration.isLogCorrelationEnabled()).thenReturn(true); + Transaction transaction = tracer.startTransaction(TraceContext.asRoot(), null, null).withType("request").withName("test"); + assertMdcIsEmpty(); + final CompletableFuture result = new CompletableFuture<>(); + Thread thread = new Thread(() -> { + assertMdcIsEmpty(); + try (Scope scope = transaction.activateInScope()) { + assertMdcIsEmpty(); + } + result.complete(true); + }); + thread.setContextClassLoader(ClassLoader.getPlatformClassLoader()); + thread.start(); + assertThat(result.get(1000, TimeUnit.MILLISECONDS).booleanValue()).isTrue(); + assertMdcIsEmpty(); + thread.join(); + transaction.end(); + } + + @Test + void testWithNullContextClassLoader() throws Exception { + when(loggingConfiguration.isLogCorrelationEnabled()).thenReturn(true); + Transaction transaction = tracer.startTransaction(TraceContext.asRoot(), null, null).withType("request").withName("test"); + assertMdcIsEmpty(); + final CompletableFuture result = new CompletableFuture<>(); + Thread thread = new Thread(() -> { + assertMdcIsEmpty(); + try (Scope scope = transaction.activateInScope()) { + assertMdcIsSet(transaction); + } + assertMdcIsEmpty(); + result.complete(true); + }); + thread.setContextClassLoader(null); + thread.start(); + assertThat(result.get(1000, TimeUnit.MILLISECONDS).booleanValue()).isTrue(); assertMdcIsEmpty(); thread.join(); transaction.end(); @@ -102,15 +150,17 @@ void testMdcIntegrationContextScopeInDifferentThread() throws Exception { final Span child = transaction.createSpan(); try (Scope childScope = child.activateInScope()) { assertMdcIsSet(child); + final CompletableFuture result = new CompletableFuture<>(); Thread thread = new Thread(() -> { assertMdcIsEmpty(); try (Scope otherThreadScope = child.getTraceContext().activateInScope()) { assertMdcIsSet(child); } assertMdcIsEmpty(); + result.complete(true); }); thread.start(); - thread.join(); + assertThat(result.get(1000, TimeUnit.MILLISECONDS).booleanValue()).isTrue(); assertMdcIsSet(child); } assertMdcIsSet(transaction);