Fix caller data lost in logback mdc library instrumentation (#12220)

This commit is contained in:
Lauri Tulmin 2024-09-12 22:54:52 +03:00 committed by GitHub
parent 103d160e71
commit 34740eef6a
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
2 changed files with 46 additions and 37 deletions

View File

@ -7,7 +7,7 @@ package io.opentelemetry.instrumentation.logback.mdc.v1_0;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.classic.spi.LoggerContextVO;
import ch.qos.logback.classic.spi.LoggingEventVO;
import ch.qos.logback.classic.spi.LoggingEvent;
import ch.qos.logback.core.Appender;
import ch.qos.logback.core.UnsynchronizedAppenderBase;
import ch.qos.logback.core.spi.AppenderAttachable;
@ -18,14 +18,26 @@ import io.opentelemetry.api.trace.SpanContext;
import io.opentelemetry.context.Context;
import io.opentelemetry.instrumentation.api.incubator.log.LoggingContextConstants;
import io.opentelemetry.instrumentation.logback.mdc.v1_0.internal.UnionMap;
import java.lang.reflect.InvocationTargetException;
import java.lang.reflect.Proxy;
import java.lang.reflect.Field;
import java.util.HashMap;
import java.util.Iterator;
import java.util.Map;
public class OpenTelemetryAppender extends UnsynchronizedAppenderBase<ILoggingEvent>
implements AppenderAttachable<ILoggingEvent> {
private static final Field MDC_MAP_FIELD;
static {
Field field;
try {
field = LoggingEvent.class.getDeclaredField("mdcPropertyMap");
field.setAccessible(true);
} catch (Exception exception) {
field = null;
}
MDC_MAP_FIELD = field;
}
private boolean addBaggage;
private String traceIdKey = LoggingContextConstants.TRACE_ID;
private String spanIdKey = LoggingContextConstants.SPAN_ID;
@ -59,11 +71,15 @@ public class OpenTelemetryAppender extends UnsynchronizedAppenderBase<ILoggingEv
this.traceFlagsKey = traceFlagsKey;
}
public ILoggingEvent wrapEvent(ILoggingEvent event) {
private void processEvent(ILoggingEvent event) {
if (MDC_MAP_FIELD == null || event.getClass() != LoggingEvent.class) {
return;
}
Map<String, String> eventContext = event.getMDCPropertyMap();
if (eventContext != null && eventContext.containsKey(traceIdKey)) {
// Assume already instrumented event if traceId is present.
return event;
return;
}
Map<String, String> contextData = new HashMap<>();
@ -98,32 +114,18 @@ public class OpenTelemetryAppender extends UnsynchronizedAppenderBase<ILoggingEv
? new LoggerContextVO(oldVo.getName(), eventContextMap, oldVo.getBirthTime())
: null;
ILoggingEvent wrappedEvent =
(ILoggingEvent)
Proxy.newProxyInstance(
ILoggingEvent.class.getClassLoader(),
new Class<?>[] {ILoggingEvent.class},
(proxy, method, args) -> {
if ("getMDCPropertyMap".equals(method.getName())) {
return eventContextMap;
} else if ("getLoggerContextVO".equals(method.getName())) {
return vo;
}
try {
return method.invoke(event, args);
} catch (InvocationTargetException exception) {
throw exception.getCause();
}
});
// https://github.com/qos-ch/logback/blob/9e833ec858953a2296afdc3292f8542fc08f2a45/logback-classic/src/main/java/ch/qos/logback/classic/net/LoggingEventPreSerializationTransformer.java#L29
// LoggingEventPreSerializationTransformer accepts only subclasses of LoggingEvent and
// LoggingEventVO, here we transform our wrapped event into a LoggingEventVO
return LoggingEventVO.build(wrappedEvent);
try {
MDC_MAP_FIELD.set(event, eventContextMap);
} catch (IllegalAccessException ignored) {
// setAccessible(true) was called on the field
}
((LoggingEvent) event).setLoggerContextRemoteView(vo);
}
@Override
protected void append(ILoggingEvent event) {
aai.appendLoopOnAppenders(wrapEvent(event));
processEvent(event);
aai.appendLoopOnAppenders(event);
}
@Override

View File

@ -65,18 +65,20 @@ public abstract class AbstractLogbackTest {
assertThat(events.size()).isEqualTo(2);
assertThat(events.get(0).getMessage()).isEqualTo("log message 1");
assertThat(events.get(0).getMDCPropertyMap().get(getLoggingKey("trace_id"))).isNull();
assertThat(events.get(0).getMDCPropertyMap().get(getLoggingKey("span_id"))).isNull();
assertThat(events.get(0).getMDCPropertyMap().get(getLoggingKey("trace_flags"))).isNull();
assertThat(events.get(0).getMDCPropertyMap())
.doesNotContainKeys(
getLoggingKey("trace_id"), getLoggingKey("span_id"), getLoggingKey("trace_flags"));
assertThat(events.get(0).getMDCPropertyMap().get("baggage.baggage_key"))
.isEqualTo(expectBaggage() ? "baggage_value" : null);
assertThat(events.get(0).getCallerData()).isNotNull();
assertThat(events.get(1).getMessage()).isEqualTo("log message 2");
assertThat(events.get(1).getMDCPropertyMap().get(getLoggingKey("trace_id"))).isNull();
assertThat(events.get(1).getMDCPropertyMap().get(getLoggingKey("span_id"))).isNull();
assertThat(events.get(1).getMDCPropertyMap().get(getLoggingKey("trace_flags"))).isNull();
assertThat(events.get(1).getMDCPropertyMap())
.doesNotContainKeys(
getLoggingKey("trace_id"), getLoggingKey("span_id"), getLoggingKey("trace_flags"));
assertThat(events.get(1).getMDCPropertyMap().get("baggage.baggage_key"))
.isEqualTo(expectBaggage() ? "baggage_value" : null);
assertThat(events.get(1).getCallerData()).isNotNull();
}
@Test
@ -98,12 +100,16 @@ public abstract class AbstractLogbackTest {
assertThat(events.get(0).getMDCPropertyMap().get(getLoggingKey("trace_flags"))).isEqualTo("01");
assertThat(events.get(0).getMDCPropertyMap().get("baggage.baggage_key"))
.isEqualTo(expectBaggage() ? "baggage_value" : null);
assertThat(events.get(0).getCallerData()).isNotNull();
assertThat(events.get(1).getMessage()).isEqualTo("log message 2");
assertThat(events.get(1).getMDCPropertyMap().get(getLoggingKey("trace_id"))).isNull();
assertThat(events.get(1).getMDCPropertyMap().get(getLoggingKey("span_id"))).isNull();
assertThat(events.get(1).getMDCPropertyMap().get(getLoggingKey("trace_flags"))).isNull();
assertThat(events.get(1).getMDCPropertyMap().get("baggage.baggage_key")).isNull();
assertThat(events.get(1).getMDCPropertyMap())
.doesNotContainKeys(
getLoggingKey("trace_id"),
getLoggingKey("span_id"),
getLoggingKey("trace_flags"),
"baggage.baggage_key");
assertThat(events.get(1).getCallerData()).isNotNull();
assertThat(events.get(2).getMessage()).isEqualTo("log message 3");
assertThat(events.get(2).getMDCPropertyMap().get(getLoggingKey("trace_id")))
@ -113,6 +119,7 @@ public abstract class AbstractLogbackTest {
assertThat(events.get(2).getMDCPropertyMap().get(getLoggingKey("trace_flags"))).isEqualTo("01");
assertThat(events.get(2).getMDCPropertyMap().get("baggage.baggage_key"))
.isEqualTo(expectBaggage() ? "baggage_value" : null);
assertThat(events.get(2).getCallerData()).isNotNull();
}
void runWithBaggage(Baggage baggage, Runnable runnable) {