Skip to content

Attempting System CL when Context CL is null and caching loading failure #718

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Jul 15, 2019
Merged

Attempting System CL when Context CL is null and caching loading failure #718

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
31 changes: 21 additions & 10 deletions ...apm-slf4j-plugin/src/main/java/co/elastic/apm/agent/slf4j/Slf4JMdcActivationListener.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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<ClassLoader, MethodHandle> mdcPutMethodHandleCache =
new WeakKeySoftValueLoadingCache<>(new WeakKeySoftValueLoadingCache.ValueSupplier<ClassLoader, MethodHandle>() {
Expand All @@ -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;
}
}
});
Expand All @@ -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;
}
}
});
Expand All @@ -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) {
Expand All @@ -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);
Expand All @@ -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();
}
}
52 changes: 51 additions & 1 deletion ...slf4j-plugin/src/test/java/co/elastic/apm/agent/slf4j/Slf4JMdcActivationListenerTest.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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<Boolean> 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<Boolean> 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<Boolean> 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();
Expand All @@ -102,15 +150,17 @@ void testMdcIntegrationContextScopeInDifferentThread() throws Exception {
final Span child = transaction.createSpan();
try (Scope childScope = child.activateInScope()) {
assertMdcIsSet(child);
final CompletableFuture<Boolean> 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);
Expand Down