Skip to content
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

Fix logging integration #500

Merged
merged 4 commits into from
Mar 5, 2019
Merged

Fix logging integration #500

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
2fba42d
Fix logging integration
eyalkoren Feb 25, 2019
ab6f09d
Applying review suggestions
eyalkoren Mar 5, 2019
8f3c13d
Merge remote-tracking branch 'upstream/master' into fix-logging-instr…
eyalkoren Mar 5, 2019
6fc8580
Removing a small leftover
eyalkoren Mar 5, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 2 additions & 2 deletions apm-agent-core/src/main/java/co/elastic/apm/agent/impl/ActivationListener.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -35,7 +35,7 @@ public interface ActivationListener {
* @param context the {@link TraceContextHolder} which is being activated
* @throws Throwable if there was an error while calling this method
*/
void onActivate(TraceContextHolder<?> context) throws Throwable;
void beforeActivate(TraceContextHolder<?> context) throws Throwable;

/**
* A callback for {@link TraceContextHolder#deactivate()}
Expand All @@ -46,5 +46,5 @@ public interface ActivationListener {
*
* @throws Throwable if there was an error while calling this method
*/
void onDeactivate() throws Throwable;
void afterDeactivate() throws Throwable;
}
10 changes: 5 additions & 5 deletions apm-agent-core/src/main/java/co/elastic/apm/agent/impl/transaction/TraceContextHolder.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -63,17 +63,17 @@ protected TraceContextHolder(ElasticApmTracer tracer) {
public abstract boolean isChildOf(TraceContextHolder other);

public T activate() {
tracer.activate(this);
List<ActivationListener> activationListeners = tracer.getActivationListeners();
for (int i = 0; i < activationListeners.size(); i++) {
try {
activationListeners.get(i).onActivate(this);
activationListeners.get(i).beforeActivate(this);
} catch (Error e) {
throw e;
} catch (Throwable t) {
logger.warn("Exception while calling {}#onActivate", activationListeners.get(i).getClass().getSimpleName(), t);
logger.warn("Exception while calling {}#beforeActivate", activationListeners.get(i).getClass().getSimpleName(), t);
}
}
tracer.activate(this);
return (T) this;
}

Expand All @@ -82,11 +82,11 @@ public T deactivate() {
List<ActivationListener> activationListeners = tracer.getActivationListeners();
for (int i = 0; i < activationListeners.size(); i++) {
try {
activationListeners.get(i).onDeactivate();
activationListeners.get(i).afterDeactivate();
} catch (Error e) {
throw e;
} catch (Throwable t) {
logger.warn("Exception while calling {}#onDeactivate", activationListeners.get(i).getClass().getSimpleName(), t);
logger.warn("Exception while calling {}#afterDeactivate", activationListeners.get(i).getClass().getSimpleName(), t);
}
}
return (T) this;
Expand Down
53 changes: 38 additions & 15 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 @@ -22,7 +22,6 @@
import co.elastic.apm.agent.cache.WeakKeySoftValueLoadingCache;
import co.elastic.apm.agent.impl.ActivationListener;
import co.elastic.apm.agent.impl.ElasticApmTracer;
import co.elastic.apm.agent.impl.transaction.Span;
import co.elastic.apm.agent.impl.transaction.TraceContext;
import co.elastic.apm.agent.impl.transaction.TraceContextHolder;
import co.elastic.apm.agent.logging.LoggingConfiguration;
Expand All @@ -40,6 +39,7 @@ 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 final WeakKeySoftValueLoadingCache<ClassLoader, MethodHandle> mdcPutMethodHandleCache =
new WeakKeySoftValueLoadingCache<>(new WeakKeySoftValueLoadingCache.ValueSupplier<ClassLoader, MethodHandle>() {
@Nullable
Expand Down Expand Up @@ -70,35 +70,58 @@ public MethodHandle get(ClassLoader classLoader) {
});
@Nullable
private LoggingConfiguration config;
@Nullable
private ElasticApmTracer tracer;

@Override
public void init(ElasticApmTracer tracer) {
this.tracer = tracer;
config = tracer.getConfig(LoggingConfiguration.class);
}

@Override
public void onActivate(TraceContextHolder<?> context) throws Throwable {
if (config != null && config.isLogCorrelationEnabled() && context.isSampled()) {
MethodHandle put = mdcPutMethodHandleCache.get(Thread.currentThread().getContextClassLoader());
TraceContext traceContext = context.getTraceContext();
public void beforeActivate(TraceContextHolder<?> context) throws Throwable {
if (config != null && config.isLogCorrelationEnabled()) {
ClassLoader contextClassLoader = Thread.currentThread().getContextClassLoader();

MethodHandle put = mdcPutMethodHandleCache.get(contextClassLoader);
if (put != null) {
put.invokeExact(TRACE_ID, traceContext.getTraceId().toString());
String idKey = context instanceof Span ? SPAN_ID : TRANSACTION_ID;
put.invokeExact(idKey, traceContext.getId().toString());
TraceContext traceContext = context.getTraceContext();
if (tracer != null) {
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());
}
}
}
}
}

@Override
public void onDeactivate() throws Throwable {
public void afterDeactivate() throws Throwable {
if (config != null && config.isLogCorrelationEnabled()) {
MethodHandle remove = mdcRemoveMethodHandleCache.get(Thread.currentThread().getContextClassLoader());
if (remove != null) {
remove.invokeExact(TRACE_ID);
remove.invokeExact(SPAN_ID);
remove.invokeExact(TRANSACTION_ID);

ClassLoader contextClassLoader = Thread.currentThread().getContextClassLoader();
if (tracer != null) {
TraceContextHolder active = tracer.getActive();

MethodHandle remove = mdcRemoveMethodHandleCache.get(contextClassLoader);
if (remove != null) {
remove.invokeExact(SPAN_ID);
if (active == null) {
remove.invokeExact(TRACE_ID);
remove.invokeExact(TRANSACTION_ID);
}
}

if (active != null) {
MethodHandle put = mdcPutMethodHandleCache.get(contextClassLoader);
if (put != null) {
put.invokeExact(SPAN_ID, active.getTraceContext().getId().toString());
}
}
}
}
}

}
48 changes: 44 additions & 4 deletions ...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 @@ -22,6 +22,8 @@
import co.elastic.apm.agent.AbstractInstrumentationTest;
import co.elastic.apm.agent.configuration.SpyConfiguration;
import co.elastic.apm.agent.impl.Scope;
import co.elastic.apm.agent.impl.transaction.AbstractSpan;
import co.elastic.apm.agent.impl.transaction.Span;
import co.elastic.apm.agent.impl.transaction.Transaction;
import co.elastic.apm.agent.logging.LoggingConfiguration;
import org.junit.jupiter.api.BeforeEach;
Expand Down Expand Up @@ -51,13 +53,23 @@ void testMdcIntegration() {
assertMdcIsEmpty();
try (Scope scope = transaction.activateInScope()) {
assertMdcIsSet(transaction);
Span child = transaction.createSpan();
try (Scope childScope = child.activateInScope()) {
assertMdcIsSet(child);
Span grandchild = child.createSpan();
try (Scope grandchildScope = grandchild.activateInScope()) {
assertMdcIsSet(grandchild);
}
assertMdcIsSet(child);
}
assertMdcIsSet(transaction);
}
assertMdcIsEmpty();
transaction.end();
}

@Test
void testMdcIntegrationScopeInDifferentThread() throws Exception {
void testMdcIntegrationTransactionScopeInDifferentThread() throws Exception {
when(loggingConfiguration.isLogCorrelationEnabled()).thenReturn(true);
Transaction transaction = tracer.startTransaction().withType("request").withName("test");
assertMdcIsEmpty();
Expand All @@ -74,6 +86,33 @@ void testMdcIntegrationScopeInDifferentThread() throws Exception {
transaction.end();
}

@Test
void testMdcIntegrationContextScopeInDifferentThread() throws Exception {
when(loggingConfiguration.isLogCorrelationEnabled()).thenReturn(true);
final Transaction transaction = tracer.startTransaction().withType("request").withName("test");
assertMdcIsEmpty();
try (Scope scope = transaction.activateInScope()) {
assertMdcIsSet(transaction);
final Span child = transaction.createSpan();
try (Scope childScope = child.activateInScope()) {
assertMdcIsSet(child);
Thread thread = new Thread(() -> {
assertMdcIsEmpty();
try (Scope otherThreadScope = child.getTraceContext().activateInScope()) {
assertMdcIsSet(child);
}
assertMdcIsEmpty();
});
thread.start();
thread.join();
assertMdcIsSet(child);
}
assertMdcIsSet(transaction);
}
assertMdcIsEmpty();
transaction.end();
}

@Test
void testDisablingAtRuntimeNotPossible() throws IOException {
assertThat(loggingConfiguration.isLogCorrelationEnabled()).isFalse();
Expand All @@ -85,9 +124,10 @@ void testDisablingAtRuntimeNotPossible() throws IOException {
assertThat(loggingConfiguration.isLogCorrelationEnabled()).isTrue();
}

private void assertMdcIsSet(Transaction transaction) {
assertThat(MDC.get("trace.id")).isEqualTo(transaction.getTraceContext().getTraceId().toString());
assertThat(MDC.get("transaction.id")).isEqualTo(transaction.getTraceContext().getId().toString());
private void assertMdcIsSet(AbstractSpan span) {
assertThat(MDC.get("trace.id")).isEqualTo(span.getTraceContext().getTraceId().toString());
assertThat(MDC.get("transaction.id")).isEqualTo(span.getTraceContext().getTransactionId().toString());
assertThat(MDC.get("span.id")).isEqualTo(span.getTraceContext().getId().toString());
}

private void assertMdcIsEmpty() {
Expand Down