Support slf4j to log4j2 (#7656)

instrumentation/log4j/log4j-appender-2.17/javaagent/build.gradle.kts

@@ -11,6 +11,8 @@ muzzle {
   }
 }
 
+val testLatestDeps = findProperty("testLatestDeps") as Boolean
+
 dependencies {
   library("org.apache.logging.log4j:log4j-core:2.17.0")
 
@@ -21,16 +23,33 @@ dependencies {
 
   testImplementation("org.awaitility:awaitility")
 
+  // this dependency is needed for the slf4j->log4j test
+  if (testLatestDeps) {
+    testImplementation("org.apache.logging.log4j:log4j-slf4j2-impl:2.19.0")
+  } else {
+    // log4j 2.17 doesn't have an slf4j2 bridge
+    testImplementation("org.apache.logging.log4j:log4j-slf4j-impl:2.17.0")
+    testImplementation("org.slf4j:slf4j-api") {
+      version {
+        strictly("1.7.36")
+      }
+    }
+  }
+
   // this is needed for the async logging test
   testImplementation("com.lmax:disruptor:3.4.2")
 }
 
+tasks.withType<Test>().configureEach {
+  systemProperty("testLatestDeps", testLatestDeps)
+}
+
 tasks {
   val testAsync by registering(Test::class) {
     jvmArgs("-DLog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector")
   }
 
-  named<Test>("test") {
+  check {
     dependsOn(testAsync)
   }
 }
@@ -42,3 +61,10 @@ tasks.withType<Test>().configureEach {
   jvmArgs("-Dotel.instrumentation.log4j-appender.experimental-log-attributes=true")
   jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-marker-attribute=true")
 }
+
+configurations {
+  testImplementation {
+    // this is needed for the slf4j->log4j test
+    exclude("ch.qos.logback", "logback-classic")
+  }
+}

instrumentation/log4j/log4j-appender-2.17/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/log4j/appender/v2_17/Log4jAppenderInstrumentation.java

@@ -52,6 +52,17 @@ class Log4jAppenderInstrumentation implements TypeInstrumentation {
             .and(takesArgument(4, named("org.apache.logging.log4j.message.Message")))
             .and(takesArgument(5, Throwable.class)),
         Log4jAppenderInstrumentation.class.getName() + "$LogAdvice");
+    transformer.applyAdviceToMethod(
+        isMethod()
+            .and(isProtected().or(isPublic()))
+            .and(named("logMessage"))
+            .and(takesArguments(5))
+            .and(takesArgument(0, String.class))
+            .and(takesArgument(1, named("org.apache.logging.log4j.Level")))
+            .and(takesArgument(2, named("org.apache.logging.log4j.Marker")))
+            .and(takesArgument(3, named("org.apache.logging.log4j.message.Message")))
+            .and(takesArgument(4, Throwable.class)),
+        Log4jAppenderInstrumentation.class.getName() + "$LogMessageAdvice");
   }
 
   @SuppressWarnings("unused")
@@ -78,4 +89,29 @@ class Log4jAppenderInstrumentation implements TypeInstrumentation {
       callDepth.decrementAndGet();
     }
   }
+
+  @SuppressWarnings("unused")
+  public static class LogMessageAdvice {
+
+    @Advice.OnMethodEnter(suppress = Throwable.class)
+    public static void methodEnter(
+        @Advice.This Logger logger,
+        @Advice.Argument(1) Level level,
+        @Advice.Argument(2) Marker marker,
+        @Advice.Argument(3) Message message,
+        @Advice.Argument(4) Throwable t,
+        @Advice.Local("otelCallDepth") CallDepth callDepth) {
+      // need to track call depth across all loggers in order to avoid double capture when one
+      // logging framework delegates to another
+      callDepth = CallDepth.forClass(LoggerProvider.class);
+      if (callDepth.getAndIncrement() == 0) {
+        Log4jHelper.capture(logger, level, marker, message, t);
+      }
+    }
+
+    @Advice.OnMethodExit(onThrowable = Throwable.class, suppress = Throwable.class)
+    public static void methodExit(@Advice.Local("otelCallDepth") CallDepth callDepth) {
+      callDepth.decrementAndGet();
+    }
+  }
 }

instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4jTest.java

@@ -0,0 +1,177 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+package io.opentelemetry.instrumentation.log4j.appender.v2_17;
+
+import static io.opentelemetry.sdk.testing.assertj.LogAssertions.assertThat;
+import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.equalTo;
+import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.satisfies;
+
+import io.opentelemetry.api.common.AttributeKey;
+import io.opentelemetry.api.logs.Severity;
+import io.opentelemetry.instrumentation.testing.junit.AgentInstrumentationExtension;
+import io.opentelemetry.instrumentation.testing.junit.InstrumentationExtension;
+import io.opentelemetry.sdk.common.InstrumentationScopeInfo;
+import io.opentelemetry.sdk.logs.data.LogRecordData;
+import io.opentelemetry.semconv.trace.attributes.SemanticAttributes;
+import java.util.stream.Stream;
+import org.junit.jupiter.api.Test;
+import org.junit.jupiter.api.extension.RegisterExtension;
+import org.junit.jupiter.params.ParameterizedTest;
+import org.junit.jupiter.params.provider.Arguments;
+import org.junit.jupiter.params.provider.MethodSource;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+import org.slf4j.MDC;
+import org.slf4j.Marker;
+import org.slf4j.MarkerFactory;
+
+class Slf4jToLog4jTest {
+
+  @RegisterExtension
+  static final InstrumentationExtension testing = AgentInstrumentationExtension.create();
+
+  private static final Logger logger = LoggerFactory.getLogger("abc");
+
+  private static Stream<Arguments> provideParameters() {
+    return Stream.of(
+        Arguments.of(false, false),
+        Arguments.of(false, true),
+        Arguments.of(true, false),
+        Arguments.of(true, true));
+  }
+
+  @ParameterizedTest
+  @MethodSource("provideParameters")
+  public void test(boolean logException, boolean withParent) throws InterruptedException {
+    test(Logger::debug, Logger::debug, logException, withParent, null, null, null);
+    testing.clearData();
+    test(Logger::info, Logger::info, logException, withParent, "abc", Severity.INFO, "INFO");
+    testing.clearData();
+    test(Logger::warn, Logger::warn, logException, withParent, "abc", Severity.WARN, "WARN");
+    testing.clearData();
+    test(Logger::error, Logger::error, logException, withParent, "abc", Severity.ERROR, "ERROR");
+    testing.clearData();
+  }
+
+  private static void test(
+      OneArgLoggerMethod oneArgLoggerMethod,
+      TwoArgLoggerMethod twoArgLoggerMethod,
+      boolean logException,
+      boolean withParent,
+      String expectedLoggerName,
+      Severity expectedSeverity,
+      String expectedSeverityText)
+      throws InterruptedException {
+
+    // when
+    if (withParent) {
+      testing.runWithSpan(
+          "parent", () -> performLogging(oneArgLoggerMethod, twoArgLoggerMethod, logException));
+    } else {
+      performLogging(oneArgLoggerMethod, twoArgLoggerMethod, logException);
+    }
+
+    // then
+    if (withParent) {
+      testing.waitForTraces(1);
+    }
+
+    if (expectedSeverity != null) {
+      LogRecordData log = testing.waitForLogRecords(1).get(0);
+      assertThat(log)
+          .hasBody("xyz: 123")
+          .hasInstrumentationScope(InstrumentationScopeInfo.builder(expectedLoggerName).build())
+          .hasSeverity(expectedSeverity)
+          .hasSeverityText(expectedSeverityText);
+      if (logException) {
+        assertThat(log)
+            .hasAttributesSatisfyingExactly(
+                equalTo(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName()),
+                equalTo(SemanticAttributes.THREAD_ID, Thread.currentThread().getId()),
+                equalTo(SemanticAttributes.EXCEPTION_TYPE, IllegalStateException.class.getName()),
+                equalTo(SemanticAttributes.EXCEPTION_MESSAGE, "hello"),
+                satisfies(
+                    SemanticAttributes.EXCEPTION_STACKTRACE,
+                    v -> v.contains(Slf4jToLog4jTest.class.getName())));
+      } else {
+        assertThat(log)
+            .hasAttributesSatisfyingExactly(
+                equalTo(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName()),
+                equalTo(SemanticAttributes.THREAD_ID, Thread.currentThread().getId()));
+      }
+
+      if (withParent) {
+        assertThat(log).hasSpanContext(testing.spans().get(0).getSpanContext());
+      } else {
+        assertThat(log.getSpanContext().isValid()).isFalse();
+      }
+
+    } else {
+      Thread.sleep(500); // sleep a bit just to make sure no log is captured
+      assertThat(testing.logRecords()).isEmpty();
+    }
+  }
+
+  @Test
+  void testMdc() {
+    MDC.put("key1", "val1");
+    MDC.put("key2", "val2");
+    try {
+      logger.info("xyz: {}", 123);
+    } finally {
+      MDC.clear();
+    }
+
+    LogRecordData log = testing.waitForLogRecords(1).get(0);
+    assertThat(log)
+        .hasBody("xyz: 123")
+        .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build())
+        .hasSeverity(Severity.INFO)
+        .hasSeverityText("INFO")
+        .hasAttributesSatisfyingExactly(
+            equalTo(AttributeKey.stringKey("log4j.context_data.key1"), "val1"),
+            equalTo(AttributeKey.stringKey("log4j.context_data.key2"), "val2"),
+            equalTo(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName()),
+            equalTo(SemanticAttributes.THREAD_ID, Thread.currentThread().getId()));
+  }
+
+  @Test
+  public void testMarker() {
+
+    String markerName = "aMarker";
+    Marker marker = MarkerFactory.getMarker(markerName);
+
+    logger.info(marker, "Message");
+
+    LogRecordData log = testing.waitForLogRecords(1).get(0);
+    assertThat(log)
+        .hasAttributesSatisfyingExactly(
+            equalTo(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName()),
+            equalTo(SemanticAttributes.THREAD_ID, Thread.currentThread().getId()),
+            equalTo(AttributeKey.stringKey("log4j.marker"), markerName));
+  }
+
+  private static void performLogging(
+      OneArgLoggerMethod oneArgLoggerMethod,
+      TwoArgLoggerMethod twoArgLoggerMethod,
+      boolean logException) {
+    if (logException) {
+      twoArgLoggerMethod.call(logger, "xyz: {}", 123, new IllegalStateException("hello"));
+    } else {
+      oneArgLoggerMethod.call(logger, "xyz: {}", 123);
+    }
+  }
+
+  @FunctionalInterface
+  interface OneArgLoggerMethod {
+    void call(Logger logger, String msg, Object arg);
+  }
+
+  @FunctionalInterface
+  interface TwoArgLoggerMethod {
+    void call(Logger logger, String msg, Object arg1, Object arg2);
+  }
+}

instrumentation/logback/logback-appender-1.0/javaagent/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/LogbackTest.java

@@ -121,9 +121,7 @@ class LogbackTest {
     if (withParent) {
       testing.runWithSpan(
           "parent",
-          () -> {
+          () -> performLogging(logger, oneArgLoggerMethod, twoArgLoggerMethod, logException));
-            performLogging(logger, oneArgLoggerMethod, twoArgLoggerMethod, logException);
-          });
     } else {
       performLogging(logger, oneArgLoggerMethod, twoArgLoggerMethod, logException);
     }

testing-common/src/main/java/io/opentelemetry/instrumentation/testing/AgentTestRunner.java

@@ -26,8 +26,12 @@ import org.slf4j.LoggerFactory;
  */
 public final class AgentTestRunner extends InstrumentationTestRunner {
   static {
-    LoggerUtils.setLevel(LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME), Level.WARN);
+    try {
-    LoggerUtils.setLevel(LoggerFactory.getLogger("io.opentelemetry"), Level.DEBUG);
+      LoggerUtils.setLevel(LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME), Level.WARN);
+      LoggerUtils.setLevel(LoggerFactory.getLogger("io.opentelemetry"), Level.DEBUG);
+    } catch (NoClassDefFoundError e) {
+      // this happens when excluding logback in order to test slf4j -> log4j2
+    }
   }
 
   private static final AgentTestRunner INSTANCE = new AgentTestRunner();