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

Author: laurit

instrumentation/logback/logback-mdc-1.0/library/src/main/java/io/opentelemetry/instrumentation/logback/mdc/v1_0/OpenTelemetryAppender.java

@@ -7,7 +7,7 @@
 
 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.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 void setTraceFlagsKey(String traceFlagsKey) {
     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 ILoggingEvent wrapEvent(ILoggingEvent event) {
             ? 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

instrumentation/logback/logback-mdc-1.0/testing/src/main/java/io/opentelemetry/instrumentation/logback/mdc/v1_0/AbstractLogbackTest.java

@@ -65,18 +65,20 @@ void testNoIdsWhenNoSpan() {
 
     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 @@ void testIdsWhenSpan() {
     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 @@ void testIdsWhenSpan() {
     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) {