Add logback mdc instrumentation to spring boot starter (#12515)

laurit · web-flow · commit 0521ac185025 · 2024-10-29T09:00:48.000-07:00
diff --git a/instrumentation/logback/logback-appender-1.0/library/src/main/java/io/opentelemetry/instrumentation/logback/appender/v1_0/OpenTelemetryAppender.java b/instrumentation/logback/logback-appender-1.0/library/src/main/java/io/opentelemetry/instrumentation/logback/appender/v1_0/OpenTelemetryAppender.java
@@ -204,7 +204,10 @@ public void setOpenTelemetry(OpenTelemetry openTelemetry) {
     try {
       // minimize scope of write lock
       this.openTelemetry = openTelemetry;
-      this.eventsToReplay.drainTo(eventsToReplay);
+      // tests set openTelemetry to null, ignore it
+      if (openTelemetry != null) {
+        this.eventsToReplay.drainTo(eventsToReplay);
+      }
     } finally {
       writeLock.unlock();
     }
diff --git a/instrumentation/spring/spring-boot-autoconfigure/build.gradle.kts b/instrumentation/spring/spring-boot-autoconfigure/build.gradle.kts
@@ -50,6 +50,7 @@ dependencies {
   implementation(project(":instrumentation:log4j:log4j-appender-2.17:library"))
   compileOnly("org.apache.logging.log4j:log4j-core:2.17.0")
   implementation(project(":instrumentation:logback:logback-appender-1.0:library"))
+  implementation(project(":instrumentation:logback:logback-mdc-1.0:library"))
   compileOnly("ch.qos.logback:logback-classic:1.0.0")
   implementation(project(":instrumentation:jdbc:library"))
 
diff --git a/instrumentation/spring/spring-boot-autoconfigure/src/main/java/io/opentelemetry/instrumentation/spring/autoconfigure/internal/instrumentation/logging/LogbackAppenderInstaller.java b/instrumentation/spring/spring-boot-autoconfigure/src/main/java/io/opentelemetry/instrumentation/spring/autoconfigure/internal/instrumentation/logging/LogbackAppenderInstaller.java
@@ -19,7 +19,19 @@
 class LogbackAppenderInstaller {
 
   static void install(ApplicationEnvironmentPreparedEvent applicationEnvironmentPreparedEvent) {
-    Optional<OpenTelemetryAppender> existingOpenTelemetryAppender = findOpenTelemetryAppender();
+    Optional<io.opentelemetry.instrumentation.logback.mdc.v1_0.OpenTelemetryAppender>
+        existingMdcAppender =
+            findAppender(
+                io.opentelemetry.instrumentation.logback.mdc.v1_0.OpenTelemetryAppender.class);
+    if (existingMdcAppender.isPresent()) {
+      initializeMdcAppenderFromProperties(
+          applicationEnvironmentPreparedEvent, existingMdcAppender.get());
+    } else if (isLogbackMdcAppenderAddable(applicationEnvironmentPreparedEvent)) {
+      addMdcAppender(applicationEnvironmentPreparedEvent);
+    }
+
+    Optional<OpenTelemetryAppender> existingOpenTelemetryAppender =
+        findAppender(OpenTelemetryAppender.class);
     if (existingOpenTelemetryAppender.isPresent()) {
       reInitializeOpenTelemetryAppender(
           existingOpenTelemetryAppender, applicationEnvironmentPreparedEvent);
@@ -30,13 +42,22 @@ static void install(ApplicationEnvironmentPreparedEvent applicationEnvironmentPr
 
   private static boolean isLogbackAppenderAddable(
       ApplicationEnvironmentPreparedEvent applicationEnvironmentPreparedEvent) {
+    return isAppenderAddable(
+        applicationEnvironmentPreparedEvent, "otel.instrumentation.logback-appender.enabled");
+  }
+
+  private static boolean isLogbackMdcAppenderAddable(
+      ApplicationEnvironmentPreparedEvent applicationEnvironmentPreparedEvent) {
+    return isAppenderAddable(
+        applicationEnvironmentPreparedEvent, "otel.instrumentation.logback-mdc.enabled");
+  }
+
+  private static boolean isAppenderAddable(
+      ApplicationEnvironmentPreparedEvent applicationEnvironmentPreparedEvent, String property) {
     boolean otelSdkDisabled =
         evaluateBooleanProperty(applicationEnvironmentPreparedEvent, "otel.sdk.disabled", false);
     boolean logbackInstrumentationEnabled =
-        evaluateBooleanProperty(
-            applicationEnvironmentPreparedEvent,
-            "otel.instrumentation.logback-appender.enabled",
-            true);
+        evaluateBooleanProperty(applicationEnvironmentPreparedEvent, property, true);
     return !otelSdkDisabled && logbackInstrumentationEnabled;
   }
 
@@ -133,6 +154,58 @@ private static void initializeOpenTelemetryAppenderFromProperties(
     }
   }
 
+  private static void addMdcAppender(
+      ApplicationEnvironmentPreparedEvent applicationEnvironmentPreparedEvent) {
+    ch.qos.logback.classic.Logger logger =
+        (ch.qos.logback.classic.Logger)
+            LoggerFactory.getILoggerFactory().getLogger(Logger.ROOT_LOGGER_NAME);
+    io.opentelemetry.instrumentation.logback.mdc.v1_0.OpenTelemetryAppender openTelemetryAppender =
+        new io.opentelemetry.instrumentation.logback.mdc.v1_0.OpenTelemetryAppender();
+    initializeMdcAppenderFromProperties(applicationEnvironmentPreparedEvent, openTelemetryAppender);
+    openTelemetryAppender.start();
+    logger.addAppender(openTelemetryAppender);
+  }
+
+  private static void initializeMdcAppenderFromProperties(
+      ApplicationEnvironmentPreparedEvent applicationEnvironmentPreparedEvent,
+      io.opentelemetry.instrumentation.logback.mdc.v1_0.OpenTelemetryAppender
+          openTelemetryAppender) {
+
+    // Implemented in the same way as the
+    // org.springframework.boot.context.logging.LoggingApplicationListener, config properties not
+    // available
+    Boolean addBaggage =
+        evaluateBooleanProperty(
+            applicationEnvironmentPreparedEvent, "otel.instrumentation.logback-mdc.add-baggage");
+    if (addBaggage != null) {
+      openTelemetryAppender.setAddBaggage(addBaggage);
+    }
+
+    String traceIdKey =
+        applicationEnvironmentPreparedEvent
+            .getEnvironment()
+            .getProperty("otel.instrumentation.common.logging.trace-id", String.class);
+    if (traceIdKey != null) {
+      openTelemetryAppender.setTraceIdKey(traceIdKey);
+    }
+
+    String spanIdKey =
+        applicationEnvironmentPreparedEvent
+            .getEnvironment()
+            .getProperty("otel.instrumentation.common.logging.span-id", String.class);
+    if (spanIdKey != null) {
+      openTelemetryAppender.setSpanIdKey(spanIdKey);
+    }
+
+    String traceFlagsKey =
+        applicationEnvironmentPreparedEvent
+            .getEnvironment()
+            .getProperty("otel.instrumentation.common.logging.trace-flags", String.class);
+    if (traceFlagsKey != null) {
+      openTelemetryAppender.setTraceFlagsKey(traceFlagsKey);
+    }
+  }
+
   private static Boolean evaluateBooleanProperty(
       ApplicationEnvironmentPreparedEvent applicationEnvironmentPreparedEvent, String property) {
     return applicationEnvironmentPreparedEvent
@@ -149,7 +222,7 @@ private static boolean evaluateBooleanProperty(
         .getProperty(property, Boolean.class, defaultValue);
   }
 
-  private static Optional<OpenTelemetryAppender> findOpenTelemetryAppender() {
+  private static <T> Optional<T> findAppender(Class<T> appenderClass) {
     ILoggerFactory loggerFactorySpi = LoggerFactory.getILoggerFactory();
     if (!(loggerFactorySpi instanceof LoggerContext)) {
       return Optional.empty();
@@ -159,8 +232,8 @@ private static Optional<OpenTelemetryAppender> findOpenTelemetryAppender() {
       Iterator<Appender<ILoggingEvent>> appenderIterator = logger.iteratorForAppenders();
       while (appenderIterator.hasNext()) {
         Appender<ILoggingEvent> appender = appenderIterator.next();
-        if (appender instanceof OpenTelemetryAppender) {
-          OpenTelemetryAppender openTelemetryAppender = (OpenTelemetryAppender) appender;
+        if (appenderClass.isInstance(appender)) {
+          T openTelemetryAppender = appenderClass.cast(appender);
           return Optional.of(openTelemetryAppender);
         }
       }
diff --git a/instrumentation/spring/spring-boot-autoconfigure/src/main/resources/META-INF/additional-spring-configuration-metadata.json b/instrumentation/spring/spring-boot-autoconfigure/src/main/resources/META-INF/additional-spring-configuration-metadata.json
@@ -416,6 +416,36 @@
       "type": "java.util.List<java.lang.String>",
       "description": "MDC attributes to capture. Use the wildcard character <code>*</code> to capture all attributes."
     },
+    {
+      "name": "otel.instrumentation.logback-mdc.enabled",
+      "type": "java.lang.Boolean",
+      "description": "Enable the Logback MDC instrumentation.",
+      "defaultValue": true
+    },
+    {
+      "name": "otel.instrumentation.logback-mdc.add-baggage",
+      "type": "java.lang.Boolean",
+      "description": "Enable exposing baggage attributes through MDC.",
+      "defaultValue": false
+    },
+    {
+      "name": "otel.instrumentation.common.logging.trace-id",
+      "type": "java.lang.String",
+      "description": "Customize MDC key name for the trace id.",
+      "defaultValue": "trace_id"
+    },
+    {
+      "name": "otel.instrumentation.common.logging.span-id",
+      "type": "java.lang.String",
+      "description": "Customize MDC key name for the span id.",
+      "defaultValue": "span_id"
+    },
+    {
+      "name": "otel.instrumentation.common.logging.trace-flags",
+      "type": "java.lang.String",
+      "description": "Customize MDC key name for the trace flags.",
+      "defaultValue": "trace_flags"
+    },
     {
       "name": "otel.instrumentation.micrometer.enabled",
       "type": "java.lang.Boolean",
diff --git a/instrumentation/spring/spring-boot-autoconfigure/src/testLogbackAppender/java/io/opentelemetry/instrumentation/spring/autoconfigure/internal/instrumentation/logging/LogbackAppenderTest.java b/instrumentation/spring/spring-boot-autoconfigure/src/testLogbackAppender/java/io/opentelemetry/instrumentation/spring/autoconfigure/internal/instrumentation/logging/LogbackAppenderTest.java
@@ -7,9 +7,15 @@
 
 import static org.assertj.core.api.Assertions.assertThat;
 
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.core.read.ListAppender;
+import ch.qos.logback.core.spi.AppenderAttachable;
 import io.opentelemetry.api.OpenTelemetry;
+import io.opentelemetry.api.baggage.Baggage;
 import io.opentelemetry.api.common.AttributeKey;
 import io.opentelemetry.api.common.Attributes;
+import io.opentelemetry.api.trace.Span;
+import io.opentelemetry.context.Scope;
 import io.opentelemetry.instrumentation.logback.appender.v1_0.OpenTelemetryAppender;
 import io.opentelemetry.instrumentation.testing.internal.AutoCleanupExtension;
 import io.opentelemetry.instrumentation.testing.junit.InstrumentationExtension;
@@ -21,6 +27,7 @@
 import org.junit.jupiter.api.BeforeEach;
 import org.junit.jupiter.api.Test;
 import org.junit.jupiter.api.extension.RegisterExtension;
+import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 import org.slf4j.MDC;
 import org.springframework.boot.SpringApplication;
@@ -66,6 +73,9 @@ void shouldInitializeAppender() {
     ConfigurableApplicationContext context = app.run();
     cleanup.deferCleanup(context);
 
+    ListAppender<ILoggingEvent> listAppender = getListAppender();
+    listAppender.list.clear();
+
     MDC.put("key1", "val1");
     MDC.put("key2", "val2");
     try {
@@ -91,6 +101,14 @@ void shouldInitializeAppender() {
                   .containsEntry(AttributeKey.stringKey("key1"), "val1")
                   .containsEntry(AttributeKey.stringKey("key2"), "val2");
             });
+
+    assertThat(listAppender.list)
+        .satisfiesExactly(
+            event ->
+                assertThat(event)
+                    .satisfies(
+                        e -> assertThat(e.getMessage()).isEqualTo("test log message"),
+                        e -> assertThat(e.getMDCPropertyMap()).containsOnlyKeys("key1", "key2")));
   }
 
   @Test
@@ -110,4 +128,123 @@ void shouldNotInitializeAppenderWhenDisabled() {
 
     assertThat(testing.logRecords()).isEmpty();
   }
+
+  @Test
+  void mdcAppender() {
+    Map<String, Object> properties = new HashMap<>();
+    properties.put("logging.config", "classpath:logback-test.xml");
+    properties.put("otel.instrumentation.logback-appender.enabled", "false");
+    properties.put("otel.instrumentation.logback-mdc.add-baggage", "true");
+    properties.put("otel.instrumentation.common.logging.trace-id", "traceid");
+    properties.put("otel.instrumentation.common.logging.span-id", "spanid");
+    properties.put("otel.instrumentation.common.logging.trace-flags", "traceflags");
+
+    SpringApplication app =
+        new SpringApplication(
+            TestingOpenTelemetryConfiguration.class, OpenTelemetryAppenderAutoConfiguration.class);
+    app.setDefaultProperties(properties);
+    ConfigurableApplicationContext context = app.run();
+    cleanup.deferCleanup(context);
+
+    ListAppender<ILoggingEvent> listAppender = getListAppender();
+    listAppender.list.clear();
+
+    try (Scope ignore = Baggage.current().toBuilder().put("key", "value").build().makeCurrent()) {
+      Span span = testing.getOpenTelemetry().getTracer("test").spanBuilder("test").startSpan();
+      try (Scope ignore2 = span.makeCurrent()) {
+        LoggerFactory.getLogger("test").info("test log message");
+      }
+    }
+
+    assertThat(testing.logRecords()).isEmpty();
+    assertThat(listAppender.list)
+        .satisfiesExactly(
+            event ->
+                assertThat(event)
+                    .satisfies(
+                        e -> assertThat(e.getMessage()).isEqualTo("test log message"),
+                        e ->
+                            assertThat(e.getMDCPropertyMap())
+                                .containsOnlyKeys(
+                                    "traceid", "spanid", "traceflags", "baggage.key")));
+  }
+
+  @Test
+  void shouldInitializeMdcAppender() {
+    Map<String, Object> properties = new HashMap<>();
+    properties.put("logging.config", "classpath:logback-no-otel-appenders.xml");
+    properties.put("otel.instrumentation.logback-appender.enabled", "false");
+
+    SpringApplication app =
+        new SpringApplication(
+            TestingOpenTelemetryConfiguration.class, OpenTelemetryAppenderAutoConfiguration.class);
+    app.setDefaultProperties(properties);
+    ConfigurableApplicationContext context = app.run();
+    cleanup.deferCleanup(context);
+
+    ListAppender<ILoggingEvent> listAppender = getListAppender();
+    listAppender.list.clear();
+
+    Span span = testing.getOpenTelemetry().getTracer("test").spanBuilder("test").startSpan();
+    try (Scope ignore = span.makeCurrent()) {
+      LoggerFactory.getLogger("test").info("test log message");
+    }
+
+    assertThat(testing.logRecords()).isEmpty();
+    assertThat(listAppender.list)
+        .satisfiesExactly(
+            event ->
+                assertThat(event)
+                    .satisfies(
+                        e -> assertThat(e.getMessage()).isEqualTo("test log message"),
+                        e ->
+                            assertThat(e.getMDCPropertyMap())
+                                .containsOnlyKeys("trace_id", "span_id", "trace_flags")));
+  }
+
+  @Test
+  void shouldNotInitializeMdcAppenderWhenDisabled() {
+    Map<String, Object> properties = new HashMap<>();
+    properties.put("logging.config", "classpath:logback-no-otel-appenders.xml");
+    properties.put("otel.instrumentation.logback-appender.enabled", "false");
+    properties.put("otel.instrumentation.logback-mdc.enabled", "false");
+
+    SpringApplication app =
+        new SpringApplication(
+            TestingOpenTelemetryConfiguration.class, OpenTelemetryAppenderAutoConfiguration.class);
+    app.setDefaultProperties(properties);
+    ConfigurableApplicationContext context = app.run();
+    cleanup.deferCleanup(context);
+
+    ListAppender<ILoggingEvent> listAppender = getListAppender();
+    listAppender.list.clear();
+
+    Span span = testing.getOpenTelemetry().getTracer("test").spanBuilder("test").startSpan();
+    try (Scope ignore = span.makeCurrent()) {
+      LoggerFactory.getLogger("test").info("test log message");
+    }
+
+    assertThat(testing.logRecords()).isEmpty();
+    assertThat(listAppender.list)
+        .satisfiesExactly(
+            event ->
+                assertThat(event)
+                    .satisfies(
+                        e -> assertThat(e.getMessage()).isEqualTo("test log message"),
+                        e -> assertThat(e.getMDCPropertyMap()).isEmpty()));
+  }
+
+  @SuppressWarnings("unchecked")
+  private static ListAppender<ILoggingEvent> getListAppender() {
+    Logger logger = LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME);
+    ch.qos.logback.classic.Logger logbackLogger = (ch.qos.logback.classic.Logger) logger;
+    ListAppender<ILoggingEvent> listAppender =
+        (ListAppender<ILoggingEvent>) logbackLogger.getAppender("List");
+    if (listAppender != null) {
+      return listAppender;
+    }
+    AppenderAttachable<?> mdcAppender =
+        (AppenderAttachable<?>) logbackLogger.getAppender("OpenTelemetryMdc");
+    return (ListAppender<ILoggingEvent>) mdcAppender.getAppender("List");
+  }
 }
diff --git a/instrumentation/spring/spring-boot-autoconfigure/src/testLogbackAppender/resources/logback-no-otel-appenders.xml b/instrumentation/spring/spring-boot-autoconfigure/src/testLogbackAppender/resources/logback-no-otel-appenders.xml
@@ -0,0 +1,18 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<configuration>
+
+  <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
+    <encoder>
+      <pattern>
+        %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n
+      </pattern>
+    </encoder>
+  </appender>
+  <appender name="List" class="ch.qos.logback.core.read.ListAppender" />
+
+  <root level="INFO">
+    <appender-ref ref="console"/>
+    <appender-ref ref="List"/>
+  </root>
+
+</configuration>
diff --git a/instrumentation/spring/spring-boot-autoconfigure/src/testLogbackAppender/resources/logback-test.xml b/instrumentation/spring/spring-boot-autoconfigure/src/testLogbackAppender/resources/logback-test.xml
@@ -12,10 +12,16 @@
     class="io.opentelemetry.instrumentation.logback.appender.v1_0.OpenTelemetryAppender">
     <captureCodeAttributes>true</captureCodeAttributes>
   </appender>
+  <appender name="List" class="ch.qos.logback.core.read.ListAppender" />
+  <appender name="OpenTelemetryMdc"
+            class="io.opentelemetry.instrumentation.logback.mdc.v1_0.OpenTelemetryAppender">
+    <appender-ref ref="List"/>
+  </appender>
 
   <root level="INFO">
     <appender-ref ref="console"/>
     <appender-ref ref="OpenTelemetry"/>
+    <appender-ref ref="OpenTelemetryMdc"/>
   </root>
 
 </configuration>
