Capture Log4j 2.x events (#182)

instrumentation/log4j-events-2.0/log4j-events-2.0.gradle

@@ -0,0 +1,41 @@
+muzzle {
+  pass {
+    group = 'org.apache.logging.log4j'
+    module = 'log4j-core'
+    versions = '(,)'
+  }
+
+  pass {
+    group = 'org.apache.logging.log4j'
+    module = 'log4j-api'
+    versions = '(,)'
+  }
+}
+
+apply from: "${rootDir}/gradle/java.gradle"
+
+apply plugin: 'org.unbroken-dome.test-sets'
+
+testSets {
+  latestDepTest {
+    dirName = 'test'
+  }
+}
+
+configurations {
+  // In order to test the real log4j library we need to remove the log4j transitive
+  // dependency 'log4j-over-slf4j' brought in by :testing which would shadow
+  // the log4j module under test using a proxy to slf4j instead.
+  testCompile.exclude group: 'org.slf4j', module: 'log4j-over-slf4j'
+}
+
+dependencies {
+  compileOnly group: 'org.apache.logging.log4j', name: 'log4j-core', version: '2.0'
+  compileOnly group: 'org.apache.logging.log4j', name: 'log4j-api', version: '2.0'
+
+  testCompile group: 'org.apache.logging.log4j', name: 'log4j-core', version: '2.0'
+  testCompile group: 'org.apache.logging.log4j', name: 'log4j-api', version: '2.0'
+
+  latestDepTestCompile group: 'org.apache.logging.log4j', name: 'log4j-core', version: '+'
+  latestDepTestCompile group: 'org.apache.logging.log4j', name: 'log4j-api', version: '+'
+}

instrumentation/log4j-events-2.0/src/main/java/io/opentelemetry/auto/instrumentation/log4jevents/v2_0/Log4jEventInstrumentation.java

@@ -0,0 +1,92 @@
+package io.opentelemetry.auto.instrumentation.log4jevents.v2_0;
+
+import static io.opentelemetry.auto.tooling.ByteBuddyElementMatchers.safeHasSuperType;
+import static net.bytebuddy.matcher.ElementMatchers.isMethod;
+import static net.bytebuddy.matcher.ElementMatchers.isProtected;
+import static net.bytebuddy.matcher.ElementMatchers.isPublic;
+import static net.bytebuddy.matcher.ElementMatchers.named;
+import static net.bytebuddy.matcher.ElementMatchers.takesArgument;
+import static net.bytebuddy.matcher.ElementMatchers.takesArguments;
+
+import com.google.auto.service.AutoService;
+import io.opentelemetry.auto.tooling.Instrumenter;
+import java.util.HashMap;
+import java.util.Map;
+import net.bytebuddy.asm.Advice;
+import net.bytebuddy.description.method.MethodDescription;
+import net.bytebuddy.description.type.TypeDescription;
+import net.bytebuddy.matcher.ElementMatcher;
+import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.message.Message;
+
+@AutoService(Instrumenter.class)
+public class Log4jEventInstrumentation extends Instrumenter.Default {
+  public Log4jEventInstrumentation() {
+    super("log4j-events");
+  }
+
+  @Override
+  public ElementMatcher<? super TypeDescription> typeMatcher() {
+    return safeHasSuperType(named("org.apache.logging.log4j.spi.AbstractLogger"));
+  }
+
+  @Override
+  public String[] helperClassNames() {
+    return new String[] {packageName + ".Log4jEvents"};
+  }
+
+  @Override
+  public Map<? extends ElementMatcher<? super MethodDescription>, String> transformers() {
+    final Map<ElementMatcher<? super MethodDescription>, String> transformers = new HashMap<>();
+    transformers.put(
+        isMethod()
+            .and(isPublic())
+            .and(named("logMessage"))
+            .and(takesArguments(5))
+            .and(takesArgument(0, named("java.lang.String")))
+            .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, named("java.lang.Throwable"))),
+        Log4jEventInstrumentation.class.getName() + "$LogMessageAdvice");
+    // log4j 2.12.1 introduced and started using this new log() method
+    transformers.put(
+        isMethod()
+            .and(isProtected())
+            .and(named("log"))
+            .and(takesArguments(6))
+            .and(takesArgument(0, named("org.apache.logging.log4j.Level")))
+            .and(takesArgument(1, named("org.apache.logging.log4j.Marker")))
+            .and(takesArgument(2, named("java.lang.String")))
+            .and(takesArgument(3, named("java.lang.StackTraceElement")))
+            .and(takesArgument(4, named("org.apache.logging.log4j.message.Message")))
+            .and(takesArgument(5, named("java.lang.Throwable"))),
+        Log4jEventInstrumentation.class.getName() + "$LogAdvice");
+    return transformers;
+  }
+
+  public static class LogMessageAdvice {
+
+    @Advice.OnMethodEnter(suppress = Throwable.class)
+    public static void methodEnter(
+        @Advice.This final Logger logger,
+        @Advice.Argument(1) final Level level,
+        @Advice.Argument(3) final Message message,
+        @Advice.Argument(4) final Throwable t) {
+      Log4jEvents.capture(logger, level, message, t);
+    }
+  }
+
+  public static class LogAdvice {
+
+    @Advice.OnMethodEnter(suppress = Throwable.class)
+    public static void methodEnter(
+        @Advice.This final Logger logger,
+        @Advice.Argument(0) final Level level,
+        @Advice.Argument(4) final Message message,
+        @Advice.Argument(5) final Throwable t) {
+      Log4jEvents.capture(logger, level, message, t);
+    }
+  }
+}

instrumentation/log4j-events-2.0/src/main/java/io/opentelemetry/auto/instrumentation/log4jevents/v2_0/Log4jEvents.java

@@ -0,0 +1,86 @@
+package io.opentelemetry.auto.instrumentation.log4jevents.v2_0;
+
+import io.opentelemetry.OpenTelemetry;
+import io.opentelemetry.auto.config.Config;
+import io.opentelemetry.trace.AttributeValue;
+import io.opentelemetry.trace.Span;
+import io.opentelemetry.trace.Tracer;
+import java.io.PrintWriter;
+import java.io.StringWriter;
+import java.util.HashMap;
+import java.util.Map;
+import lombok.extern.slf4j.Slf4j;
+import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.message.Message;
+
+@Slf4j
+public class Log4jEvents {
+
+  private static final Tracer TRACER =
+      OpenTelemetry.getTracerFactory().get("io.opentelemetry.auto.log4j-events-2.0");
+
+  public static void capture(
+      final Logger logger, final Level level, final Message message, final Throwable t) {
+
+    if (level.intLevel() > getThreshold().intLevel()) {
+      return;
+    }
+    final Span currentSpan = TRACER.getCurrentSpan();
+    if (!currentSpan.getContext().isValid()) {
+      return;
+    }
+
+    final Map<String, AttributeValue> attributes = new HashMap<>(t == null ? 2 : 3);
+    attributes.put("level", newAttributeValue(level.toString()));
+    attributes.put("loggerName", newAttributeValue(logger.getName()));
+    if (t != null) {
+      attributes.put("error.stack", newAttributeValue(toString(t)));
+    }
+    currentSpan.addEvent(message.getFormattedMessage(), attributes);
+  }
+
+  private static AttributeValue newAttributeValue(final String stringValue) {
+    return AttributeValue.stringAttributeValue(stringValue);
+  }
+
+  private static String toString(final Throwable t) {
+    final StringWriter out = new StringWriter();
+    t.printStackTrace(new PrintWriter(out));
+    return out.toString();
+  }
+
+  private static Level getThreshold() {
+    final String level = Config.get().getLogsEventsThreshold();
+    if (level == null) {
+      return Level.OFF;
+    }
+    switch (level) {
+      case "OFF":
+        return Level.OFF;
+      case "FATAL":
+        return Level.FATAL;
+      case "ERROR":
+      case "SEVERE":
+        return Level.ERROR;
+      case "WARN":
+      case "WARNING":
+        return Level.WARN;
+      case "INFO":
+        return Level.INFO;
+      case "CONFIG":
+      case "DEBUG":
+      case "FINE":
+      case "FINER":
+        return Level.DEBUG;
+      case "TRACE":
+      case "FINEST":
+        return Level.TRACE;
+      case "ALL":
+        return Level.ALL;
+      default:
+        log.error("unexpected value for {}: {}", Config.LOGS_EVENTS_THRESHOLD, level);
+        return Level.OFF;
+    }
+  }
+}

instrumentation/log4j-events-2.0/src/test/groovy/Log4jEventTest.groovy

@@ -0,0 +1,16 @@
+import io.opentelemetry.auto.test.log.events.LogEventsTestBase
+import org.apache.logging.log4j.LogManager
+
+class Log4jEventTest extends LogEventsTestBase {
+
+  static {
+    // need to initialize logger before tests to flush out init warning message:
+    // "Unable to instantiate org.fusesource.jansi.WindowsAnsiOutputStream"
+    LogManager.getLogger(Log4jEventTest)
+  }
+
+  @Override
+  Object createLogger(String name) {
+    LogManager.getLogger(name)
+  }
+}

instrumentation/log4j-events-2.0/src/test/resources/log4j2.xml

@@ -0,0 +1,14 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<!DOCTYPE Configuration>
+<Configuration status="WARN">
+  <Appenders>
+    <Console name="Console" target="SYSTEM_OUT">
+      <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
+    </Console>
+  </Appenders>
+  <Loggers>
+    <Root level="warn">
+      <AppenderRef ref="Console" />
+    </Root>
+  </Loggers>
+</Configuration>

settings.gradle

@@ -102,6 +102,7 @@ include ':instrumentation:lettuce-5.0'
 include ':instrumentation:log4j-events-1.1'
 // FIXME this instrumentation relied on scope listener
 // include ':instrumentation:log4j1'
+include ':instrumentation:log4j-events-2.0'
 // FIXME this instrumentation relied on scope listener
 // include ':instrumentation:log4j2'
 include ':instrumentation:mongo'