Capture Logback events (#183)

instrumentation/instrumentation.gradle

@@ -142,5 +142,9 @@ shadowJar {
 
   // this is for instrumentation on opentelemetry-api itself
   relocate "unshaded.io.opentelemetry", "io.opentelemetry"
+
+  // this is for instrumentation on logback
+  relocate "unshaded.ch.qos.logback", "ch.qos.logback"
+  relocate "unshaded.org.slf4j", "org.slf4j"
 }
 

instrumentation/logback-events-1.0/logback-events-1.0.gradle

@@ -0,0 +1,7 @@
+apply from: "${rootDir}/gradle/java.gradle"
+
+dependencies {
+  compileOnly project(path: ':logback-shaded-for-instrumenting', configuration: 'shadow')
+
+  testCompile project(path: ':logback-shaded-for-instrumenting', configuration: 'shadow')
+}

instrumentation/logback-events-1.0/src/main/java/io/opentelemetry/auto/instrumentation/logbackevents/LogbackEventInstrumentation.java

@@ -0,0 +1,55 @@
+package io.opentelemetry.auto.instrumentation.logbackevents;
+
+import static net.bytebuddy.matcher.ElementMatchers.isMethod;
+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 unshaded.ch.qos.logback.classic.spi.ILoggingEvent;
+
+@AutoService(Instrumenter.class)
+public class LogbackEventInstrumentation extends Instrumenter.Default {
+  public LogbackEventInstrumentation() {
+    super("logback-events");
+  }
+
+  @Override
+  public ElementMatcher<? super TypeDescription> typeMatcher() {
+    return named("unshaded.ch.qos.logback.classic.Logger");
+  }
+
+  @Override
+  public String[] helperClassNames() {
+    return new String[] {packageName + ".LogbackEvents"};
+  }
+
+  @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("callAppenders"))
+            .and(takesArguments(1))
+            .and(takesArgument(0, named("unshaded.ch.qos.logback.classic.spi.ILoggingEvent"))),
+        LogbackEventInstrumentation.class.getName() + "$CallAppendersAdvice");
+    return transformers;
+  }
+
+  public static class CallAppendersAdvice {
+
+    @Advice.OnMethodEnter(suppress = Throwable.class)
+    public static void methodEnter(@Advice.Argument(0) final ILoggingEvent event) {
+      LogbackEvents.capture(event);
+    }
+  }
+}

instrumentation/logback-events-1.0/src/main/java/io/opentelemetry/auto/instrumentation/logbackevents/LogbackEvents.java

@@ -0,0 +1,94 @@
+package io.opentelemetry.auto.instrumentation.logbackevents;
+
+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 unshaded.ch.qos.logback.classic.Level;
+import unshaded.ch.qos.logback.classic.spi.ILoggingEvent;
+import unshaded.ch.qos.logback.classic.spi.ThrowableProxy;
+
+@Slf4j
+public class LogbackEvents {
+
+  private static final Tracer TRACER =
+      OpenTelemetry.getTracerFactory().get("io.opentelemetry.auto");
+
+  public static void capture(final ILoggingEvent event) {
+
+    final Level level = event.getLevel();
+    if (level.toInt() < getThreshold().toInt()) {
+      // this needs to be configurable
+      return;
+    }
+    final Span currentSpan = TRACER.getCurrentSpan();
+    if (!currentSpan.getContext().isValid()) {
+      return;
+    }
+
+    final Object throwableProxy = event.getThrowableProxy();
+    Throwable t = null;
+    if (throwableProxy instanceof ThrowableProxy) {
+      // there is only one other subclass of ch.qos.logback.classic.spi.IThrowableProxy
+      // and it is only used for logging exceptions over the wire
+      t = ((ThrowableProxy) throwableProxy).getThrowable();
+    }
+
+    final Map<String, AttributeValue> attributes = new HashMap<>(t == null ? 2 : 3);
+    attributes.put("level", newAttributeValue(level.toString()));
+    attributes.put("loggerName", newAttributeValue(event.getLoggerName()));
+    if (t != null) {
+      attributes.put("error.stack", newAttributeValue(toString(t)));
+    }
+    currentSpan.addEvent(event.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":
+      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/logback-events-1.0/src/test/groovy/LogbackEventTest.groovy

@@ -0,0 +1,10 @@
+import io.opentelemetry.auto.test.log.events.LogEventsTestBase
+import unshaded.ch.qos.logback.classic.LoggerContext
+
+class LogbackEventTest extends LogEventsTestBase {
+
+  @Override
+  Object createLogger(String name) {
+    new LoggerContext().getLogger(name)
+  }
+}

logback-shaded-for-instrumenting/logback-shaded-for-instrumenting.gradle

@@ -0,0 +1,17 @@
+plugins {
+  id "com.github.johnrengelman.shadow"
+}
+
+apply from: "${rootDir}/gradle/java.gradle"
+
+dependencies {
+  compile group: 'ch.qos.logback', name: 'logback-classic', version: '0.9.16'
+}
+
+// Logback shaded so that it can be used in logback-event instrumentation, and then its usage can be
+// unshaded after Logback is shaded (yes, this is confusing)
+shadowJar {
+
+  relocate "ch.qos.logback", "unshaded.ch.qos.logback"
+  relocate "org.slf4j", "unshaded.org.slf4j"
+}

settings.gradle

@@ -22,6 +22,7 @@ rootProject.name = 'trace-java'
 include ':java-agent'
 include ':opentelemetry-sdk-shaded-for-testing'
 include ':opentelemetry-api-shaded-for-instrumenting'
+include ':logback-shaded-for-instrumenting'
 include ':agent-bootstrap'
 include ':agent-tooling'
 include ':load-generator'
@@ -105,6 +106,7 @@ include ':instrumentation:log4j-events-1.1'
 include ':instrumentation:log4j-events-2.0'
 // FIXME this instrumentation relied on scope listener
 // include ':instrumentation:log4j2'
+include ':instrumentation:logback-events-1.0'
 include ':instrumentation:mongo'
 include ':instrumentation:mongo:driver-3.1'
 include ':instrumentation:mongo:driver-3.7'