Add log4j 1.2 appender javaagent instrumentation (open-telemetry#4943)

* log4j1

* review feedback

* final

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

@@ -0,0 +1,31 @@
+plugins {
+  id("otel.javaagent-instrumentation")
+}
+
+muzzle {
+  pass {
+    group.set("log4j")
+    module.set("log4j")
+    versions.set("[1.2,)")
+    // version 1.2.15 has a bad dependency on javax.jms:jms:1.1 which was released as pom only
+    skip("1.2.15")
+  }
+}
+
+dependencies {
+  // 1.2 introduces MDC and there's no version earlier than 1.2.4 available
+  library("log4j:log4j:1.2.4")
+
+  compileOnly(project(":instrumentation-api-appender"))
+
+  testImplementation("org.awaitility:awaitility")
+}
+
+configurations {
+  // In order to test the real log4j library we need to remove the log4j transitive
+  // dependency 'log4j-over-slf4j' brought in by :testing-common which would shadow
+  // the log4j module under test using a proxy to slf4j instead.
+  testImplementation {
+    exclude("org.slf4j", "log4j-over-slf4j")
+  }
+}

instrumentation/log4j/log4j-appender-1.2/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/log4j/appender/v1_2/Log4jAppenderInstrumentation.java

@@ -0,0 +1,68 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+package io.opentelemetry.javaagent.instrumentation.log4j.appender.v1_2;
+
+import static net.bytebuddy.matcher.ElementMatchers.isMethod;
+import static net.bytebuddy.matcher.ElementMatchers.isProtected;
+import static net.bytebuddy.matcher.ElementMatchers.named;
+import static net.bytebuddy.matcher.ElementMatchers.takesArgument;
+import static net.bytebuddy.matcher.ElementMatchers.takesArguments;
+
+import io.opentelemetry.instrumentation.api.appender.LogEmitterProvider;
+import io.opentelemetry.javaagent.extension.instrumentation.TypeInstrumentation;
+import io.opentelemetry.javaagent.extension.instrumentation.TypeTransformer;
+import io.opentelemetry.javaagent.instrumentation.api.CallDepth;
+import net.bytebuddy.asm.Advice;
+import net.bytebuddy.description.type.TypeDescription;
+import net.bytebuddy.matcher.ElementMatcher;
+import org.apache.log4j.Category;
+import org.apache.log4j.Priority;
+
+class Log4jAppenderInstrumentation implements TypeInstrumentation {
+
+  @Override
+  public ElementMatcher<TypeDescription> typeMatcher() {
+    return named("org.apache.log4j.Category");
+  }
+
+  @Override
+  public void transform(TypeTransformer transformer) {
+    transformer.applyAdviceToMethod(
+        isMethod()
+            .and(isProtected())
+            .and(named("forcedLog"))
+            .and(takesArguments(4))
+            .and(takesArgument(0, String.class))
+            .and(takesArgument(1, named("org.apache.log4j.Priority")))
+            .and(takesArgument(2, Object.class))
+            .and(takesArgument(3, Throwable.class)),
+        Log4jAppenderInstrumentation.class.getName() + "$ForcedLogAdvice");
+  }
+
+  @SuppressWarnings("unused")
+  public static class ForcedLogAdvice {
+
+    @Advice.OnMethodEnter(suppress = Throwable.class)
+    public static void methodEnter(
+        @Advice.This final Category logger,
+        @Advice.Argument(1) final Priority level,
+        @Advice.Argument(2) final Object message,
+        @Advice.Argument(3) final Throwable t,
+        @Advice.Local("otelCallDepth") CallDepth callDepth) {
+      // need to track call depth across all loggers to avoid double capture when one logging
+      // framework delegates to another
+      callDepth = CallDepth.forClass(LogEmitterProvider.class);
+      if (callDepth.getAndIncrement() == 0) {
+        Log4jHelper.capture(logger, level, 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-1.2/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/log4j/appender/v1_2/Log4jAppenderInstrumentationModule.java

@@ -0,0 +1,26 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+package io.opentelemetry.javaagent.instrumentation.log4j.appender.v1_2;
+
+import static java.util.Collections.singletonList;
+
+import com.google.auto.service.AutoService;
+import io.opentelemetry.javaagent.extension.instrumentation.InstrumentationModule;
+import io.opentelemetry.javaagent.extension.instrumentation.TypeInstrumentation;
+import java.util.List;
+
+@AutoService(InstrumentationModule.class)
+public class Log4jAppenderInstrumentationModule extends InstrumentationModule {
+
+  public Log4jAppenderInstrumentationModule() {
+    super("log4j-appender", "log4j-appender-1.2");
+  }
+
+  @Override
+  public List<TypeInstrumentation> typeInstrumentations() {
+    return singletonList(new Log4jAppenderInstrumentation());
+  }
+}

instrumentation/log4j/log4j-appender-1.2/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/log4j/appender/v1_2/Log4jHelper.java

@@ -0,0 +1,82 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+package io.opentelemetry.javaagent.instrumentation.log4j.appender.v1_2;
+
+import io.opentelemetry.api.common.Attributes;
+import io.opentelemetry.api.common.AttributesBuilder;
+import io.opentelemetry.context.Context;
+import io.opentelemetry.instrumentation.api.appender.GlobalLogEmitterProvider;
+import io.opentelemetry.instrumentation.api.appender.LogBuilder;
+import io.opentelemetry.instrumentation.api.appender.Severity;
+import io.opentelemetry.semconv.trace.attributes.SemanticAttributes;
+import java.io.PrintWriter;
+import java.io.StringWriter;
+import org.apache.log4j.Category;
+import org.apache.log4j.Priority;
+
+public final class Log4jHelper {
+
+  // copied from org.apache.log4j.Level because it was only introduced in 1.2.12
+  private static final int TRACE_INT = 5000;
+
+  // TODO (trask) capture MDC
+  public static void capture(Category logger, Priority level, Object message, Throwable throwable) {
+    LogBuilder builder =
+        GlobalLogEmitterProvider.get().logEmitterBuilder(logger.getName()).build().logBuilder();
+
+    // message
+    if (message != null) {
+      builder.setBody(String.valueOf(message));
+    }
+
+    // level
+    if (level != null) {
+      builder.setSeverity(levelToSeverity(level));
+      builder.setSeverityText(level.toString());
+    }
+
+    // throwable
+    if (throwable != null) {
+      AttributesBuilder attributes = Attributes.builder();
+
+      // TODO (trask) extract method for recording exception into instrumentation-api-appender
+      attributes.put(SemanticAttributes.EXCEPTION_TYPE, throwable.getClass().getName());
+      attributes.put(SemanticAttributes.EXCEPTION_MESSAGE, throwable.getMessage());
+      StringWriter writer = new StringWriter();
+      throwable.printStackTrace(new PrintWriter(writer));
+      attributes.put(SemanticAttributes.EXCEPTION_STACKTRACE, writer.toString());
+
+      builder.setAttributes(attributes.build());
+    }
+
+    // span context
+    builder.setContext(Context.current());
+
+    builder.emit();
+  }
+
+  private static Severity levelToSeverity(Priority level) {
+    int lev = level.toInt();
+    if (lev <= TRACE_INT) {
+      return Severity.TRACE;
+    }
+    if (lev <= Priority.DEBUG_INT) {
+      return Severity.DEBUG;
+    }
+    if (lev <= Priority.INFO_INT) {
+      return Severity.INFO;
+    }
+    if (lev <= Priority.WARN_INT) {
+      return Severity.WARN;
+    }
+    if (lev <= Priority.ERROR_INT) {
+      return Severity.ERROR;
+    }
+    return Severity.FATAL;
+  }
+
+  private Log4jHelper() {}
+}

instrumentation/log4j/log4j-appender-1.2/javaagent/src/test/groovy/Log4j1Test.groovy

@@ -0,0 +1,90 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+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 spock.lang.Unroll
+
+import static io.opentelemetry.instrumentation.test.utils.TraceUtils.runUnderTrace
+import static org.assertj.core.api.Assertions.assertThat
+import static org.awaitility.Awaitility.await
+
+class Log4j1Test extends AgentInstrumentationSpecification {
+
+  private static final Logger logger = Logger.getLogger("abc")
+
+  @Unroll
+  def "test method=#testMethod with exception=#exception and parent=#parent"() {
+    when:
+    if (parent) {
+      runUnderTrace("parent") {
+        if (exception) {
+          logger."$testMethod"("xyz", new IllegalStateException("hello"))
+        } else {
+          logger."$testMethod"("xyz")
+        }
+      }
+    } else {
+      if (exception) {
+        logger."$testMethod"("xyz", new IllegalStateException("hello"))
+      } else {
+        logger."$testMethod"("xyz")
+      }
+    }
+
+    then:
+    if (parent) {
+      waitForTraces(1)
+    }
+
+    if (severity != null) {
+      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)
+      assertThat(log.getSeverityText()).isEqualTo(severityText)
+      if (exception) {
+        assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_TYPE)).isEqualTo(IllegalStateException.class.getName())
+        assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_MESSAGE)).isEqualTo("hello")
+        assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_STACKTRACE)).contains(Log4j1Test.name)
+      } else {
+        assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_TYPE)).isNull()
+        assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_MESSAGE)).isNull()
+        assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_STACKTRACE)).isNull()
+      }
+      if (parent) {
+        assertThat(log.getSpanContext()).isEqualTo(traces.get(0).get(0).getSpanContext())
+      } else {
+        assertThat(log.getSpanContext().isValid()).isFalse()
+      }
+    } else {
+      Thread.sleep(500) // sleep a bit just to make sure no log is captured
+      logs.size() == 0
+    }
+
+    where:
+    [args, exception, parent] << [
+      [
+        ["debug", null, null],
+        ["info", Severity.INFO, "INFO"],
+        ["warn", Severity.WARN, "WARN"],
+        ["error", Severity.ERROR, "ERROR"]
+      ],
+      [true, false],
+      [true, false]
+    ].combinations()
+
+    testMethod = args[0]
+    severity = args[1]
+    severityText = args[2]
+  }
+}

instrumentation/log4j/log4j-appender-1.2/javaagent/src/test/resources/log4j.properties

@@ -0,0 +1,3 @@
+log4j.rootLogger=INFO, CONSOLE
+log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender
+log4j.appender.CONSOLE.layout=org.apache.log4j.SimpleLayout

settings.gradle.kts

@@ -265,6 +265,7 @@ include(":instrumentation:lettuce:lettuce-5.1:testing")
 include(":instrumentation:liberty:compile-stub")
 include(":instrumentation:liberty:liberty:javaagent")
 include(":instrumentation:liberty:liberty-dispatcher:javaagent")
+include(":instrumentation:log4j:log4j-appender-1.2:javaagent")
 include(":instrumentation:log4j:log4j-mdc-1.2:javaagent")
 include(":instrumentation:log4j:log4j-thread-context:log4j-thread-context-2.7:javaagent")
 include(":instrumentation:log4j:log4j-thread-context:log4j-thread-context-2.16:javaagent")