Add log4j 1.2 appender MDC capture (#5475)

* Add log4j 1.2 appender MDC capture * Spotless
open-telemetry · Mar 2, 2022 · 4a8d6d5 · 4a8d6d5
1 parent 627f5d3
commit 4a8d6d5
Show file tree

Hide file tree

Showing 4 changed files with 95 additions and 6 deletions.
diff --git a/instrumentation/log4j/log4j-appender-1.2/javaagent/build.gradle.kts b/instrumentation/log4j/log4j-appender-1.2/javaagent/build.gradle.kts
@@ -32,5 +32,6 @@ configurations {
 
 tasks.withType<Test>().configureEach {
   // TODO run tests both with and without experimental log attributes
+  jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-mdc-attributes=*")
   jvmArgs("-Dotel.instrumentation.log4j-appender.experimental-log-attributes=true")
 }
diff --git a/...telemetry/javaagent/instrumentation/log4j/appender/v1_2/Log4jAppenderInstrumentation.java b/...telemetry/javaagent/instrumentation/log4j/appender/v1_2/Log4jAppenderInstrumentation.java
@@ -56,7 +56,7 @@ public static void methodEnter(
       // framework delegates to another
       callDepth = CallDepth.forClass(LogEmitterProvider.class);
       if (callDepth.getAndIncrement() == 0) {
-        Log4jHelper.capture(logger, level, message, t);
+        LogEventMapper.INSTANCE.capture(logger, level, message, t);
       }
     }
 

diff --git a/...tion/log4j/appender/v1_2/Log4jHelper.java → ...n/log4j/appender/v1_2/LogEventMapper.java b/...tion/log4j/appender/v1_2/Log4jHelper.java → ...n/log4j/appender/v1_2/LogEventMapper.java
@@ -5,20 +5,33 @@
 
 package io.opentelemetry.javaagent.instrumentation.log4j.appender.v1_2;
 
+import static java.util.Collections.emptyList;
+
+import io.opentelemetry.api.common.AttributeKey;
 import io.opentelemetry.api.common.Attributes;
 import io.opentelemetry.api.common.AttributesBuilder;
 import io.opentelemetry.context.Context;
 import io.opentelemetry.instrumentation.api.appender.internal.LogBuilder;
 import io.opentelemetry.instrumentation.api.appender.internal.Severity;
+import io.opentelemetry.instrumentation.api.cache.Cache;
 import io.opentelemetry.instrumentation.api.config.Config;
 import io.opentelemetry.javaagent.instrumentation.api.appender.internal.AgentLogEmitterProvider;
 import io.opentelemetry.semconv.trace.attributes.SemanticAttributes;
 import java.io.PrintWriter;
 import java.io.StringWriter;
+import java.util.Hashtable;
+import java.util.List;
+import java.util.Map;
+import java.util.stream.Collectors;
 import org.apache.log4j.Category;
+import org.apache.log4j.MDC;
 import org.apache.log4j.Priority;
 
-public final class Log4jHelper {
+public final class LogEventMapper {
+
+  private static final Cache<String, AttributeKey<String>> mdcAttributeKeys = Cache.bounded(100);
+
+  public static final LogEventMapper INSTANCE = new LogEventMapper();
 
   // copied from org.apache.log4j.Level because it was only introduced in 1.2.12
   private static final int TRACE_INT = 5000;
@@ -27,8 +40,25 @@ public final class Log4jHelper {
       Config.get()
           .getBoolean("otel.instrumentation.log4j-appender.experimental-log-attributes", false);
 
-  // TODO (trask) capture MDC
-  public static void capture(Category logger, Priority level, Object message, Throwable throwable) {
+  private final Map<String, AttributeKey<String>> captureMdcAttributes;
+
+  // cached as an optimization
+  private final boolean captureAllMdcAttributes;
+
+  private LogEventMapper() {
+    List<String> captureMdcAttributes =
+        Config.get()
+            .getList(
+                "otel.instrumentation.log4j-appender.experimental.capture-mdc-attributes",
+                emptyList());
+    this.captureMdcAttributes =
+        captureMdcAttributes.stream()
+            .collect(Collectors.toMap(attr -> attr, LogEventMapper::getMdcAttributeKey));
+    this.captureAllMdcAttributes =
+        captureMdcAttributes.size() == 1 && captureMdcAttributes.get(0).equals("*");
+  }
+
+  public void capture(Category logger, Priority level, Object message, Throwable throwable) {
     String instrumentationName = logger.getName();
     if (instrumentationName == null || instrumentationName.isEmpty()) {
       instrumentationName = "ROOT";
@@ -60,6 +90,8 @@ public static void capture(Category logger, Priority level, Object message, Thro
       attributes.put(SemanticAttributes.EXCEPTION_STACKTRACE, writer.toString());
     }
 
+    captureMdcAttributes(attributes);
+
     if (captureExperimentalAttributes) {
       Thread currentThread = Thread.currentThread();
       attributes.put(SemanticAttributes.THREAD_NAME, currentThread.getName());
@@ -74,6 +106,32 @@ public static void capture(Category logger, Priority level, Object message, Thro
     builder.emit();
   }
 
+  private void captureMdcAttributes(AttributesBuilder attributes) {
+
+    Hashtable<?, ?> context = MDC.getContext();
+
+    if (captureAllMdcAttributes) {
+      if (context != null) {
+        for (Map.Entry<?, ?> entry : context.entrySet()) {
+          attributes.put(
+              getMdcAttributeKey(String.valueOf(entry.getKey())), String.valueOf(entry.getValue()));
+        }
+      }
+      return;
+    }
+
+    for (Map.Entry<String, AttributeKey<String>> entry : captureMdcAttributes.entrySet()) {
+      Object value = context.get(entry.getKey());
+      if (value != null) {
+        attributes.put(entry.getValue(), value.toString());
+      }
+    }
+  }
+
+  private static AttributeKey<String> getMdcAttributeKey(String key) {
+    return mdcAttributeKeys.computeIfAbsent(key, k -> AttributeKey.stringKey("log4j.mdc." + k));
+  }
+
   private static Severity levelToSeverity(Priority level) {
     int lev = level.toInt();
     if (lev <= TRACE_INT) {
@@ -93,6 +151,4 @@ private static Severity levelToSeverity(Priority level) {
     }
     return Severity.FATAL;
   }
-
-  private Log4jHelper() {}
 }
diff --git a/instrumentation/log4j/log4j-appender-1.2/javaagent/src/test/groovy/Log4j1Test.groovy b/instrumentation/log4j/log4j-appender-1.2/javaagent/src/test/groovy/Log4j1Test.groovy
@@ -3,10 +3,12 @@
  * SPDX-License-Identifier: Apache-2.0
  */
 
+import io.opentelemetry.api.common.AttributeKey
 import io.opentelemetry.instrumentation.test.AgentInstrumentationSpecification
 import io.opentelemetry.sdk.logs.data.Severity
 import io.opentelemetry.semconv.trace.attributes.SemanticAttributes
 import org.apache.log4j.Logger
+import org.apache.log4j.MDC
 import spock.lang.Unroll
 
 import static org.assertj.core.api.Assertions.assertThat
@@ -90,4 +92,34 @@ class Log4j1Test extends AgentInstrumentationSpecification {
     severity = args[1]
     severityText = args[2]
   }
+
+  def "test mdc"() {
+    when:
+    MDC.put("key1", "val1")
+    MDC.put("key2", "val2")
+    try {
+      logger.info("xyz")
+    } finally {
+      MDC.remove("key1")
+      MDC.remove("key2")
+    }
+
+    then:
+
+    await()
+      .untilAsserted(
+        () -> {
+          assertThat(logs).hasSize(1)
+        })
+    def log = logs.get(0)
+    assertThat(log.getBody().asString()).isEqualTo("xyz")
+    assertThat(log.getInstrumentationLibraryInfo().getName()).isEqualTo("abc")
+    assertThat(log.getSeverity()).isEqualTo(Severity.INFO)
+    assertThat(log.getSeverityText()).isEqualTo("INFO")
+    assertThat(log.getAttributes().size()).isEqualTo(4)
+    assertThat(log.getAttributes().get(AttributeKey.stringKey("log4j.mdc.key1"))).isEqualTo("val1")
+    assertThat(log.getAttributes().get(AttributeKey.stringKey("log4j.mdc.key2"))).isEqualTo("val2")
+    assertThat(log.getAttributes().get(SemanticAttributes.THREAD_NAME)).isEqualTo(Thread.currentThread().getName())
+    assertThat(log.getAttributes().get(SemanticAttributes.THREAD_ID)).isEqualTo(Thread.currentThread().getId())
+  }
 }