Capture java util logging events (#175)

* Remove unused relocation

This relocation is not needed for instrumentation.

* Improve consistency of logs.injection naming

* Fix property based config init

* Capture java.util.logging events

* Fix shading

* Add comment about two part shading

agent-bootstrap/src/main/java/io/opentelemetry/auto/config/Config.java

@@ -57,7 +57,8 @@ public class Config {
   public static final String RUNTIME_CONTEXT_FIELD_INJECTION =
       "trace.runtime.context.field.injection";
 
-  public static final String LOGS_INJECTION_ENABLED = "logs.injection";
+  public static final String LOGS_INJECTION_ENABLED = "logs.injection.enabled";
+  public static final String LOGS_EVENTS_THRESHOLD = "logs.events.threshold";
 
   private static final boolean DEFAULT_TRACE_ENABLED = true;
   public static final boolean DEFAULT_INTEGRATIONS_ENABLED = true;
@@ -100,6 +101,22 @@ public class Config {
 
   @Getter private final boolean logsInjectionEnabled;
 
+  // mapping of threshold values to different logging frameworks:
+  //
+  // | Threshold    | JUL     | Logback | Log4j  |
+  // |--------------|---------|---------|--------|
+  // | OFF          | OFF     | OFF     | OFF    |
+  // | FATAL        | SEVERE  | ERROR   | FATAL  |
+  // | ERROR/SEVERE | SEVERE  | ERROR   | ERROR  |
+  // | WARN/WARNING | WARNING | WARN    | WARN   |
+  // | INFO         | INFO    | INFO    | INFO   |
+  // | CONFIG       | CONFIG  | DEBUG   | DEBUG  |
+  // | DEBUG/FINE   | FINE    | DEBUG   | DEBUG  |
+  // | FINER        | FINER   | DEBUG   | DEBUG  |
+  // | TRACE/FINEST | FINEST  | TRACE   | TRACE  |
+  // | ALL          | ALL     | ALL     | ALL    |
+  @Getter private final String logsEventsThreshold;
+
   @Getter private final String traceAnnotations;
 
   @Getter private final String traceMethods;
@@ -158,6 +175,8 @@ public class Config {
     logsInjectionEnabled =
         getBooleanSettingFromEnvironment(LOGS_INJECTION_ENABLED, DEFAULT_LOGS_INJECTION_ENABLED);
 
+    logsEventsThreshold = getSettingFromEnvironment(LOGS_EVENTS_THRESHOLD, null);
+
     traceAnnotations = getSettingFromEnvironment(TRACE_ANNOTATIONS, DEFAULT_TRACE_ANNOTATIONS);
 
     traceMethods = getSettingFromEnvironment(TRACE_METHODS, DEFAULT_TRACE_METHODS);
@@ -215,7 +234,9 @@ public class Config {
             properties, RUNTIME_CONTEXT_FIELD_INJECTION, parent.runtimeContextFieldInjection);
 
     logsInjectionEnabled =
-        getBooleanSettingFromEnvironment(LOGS_INJECTION_ENABLED, DEFAULT_LOGS_INJECTION_ENABLED);
+        getPropertyBooleanValue(properties, LOGS_INJECTION_ENABLED, parent.logsInjectionEnabled);
+
+    logsEventsThreshold = properties.getProperty(LOGS_EVENTS_THRESHOLD, parent.logsEventsThreshold);
 
     traceAnnotations = properties.getProperty(TRACE_ANNOTATIONS, parent.traceAnnotations);
 

instrumentation/instrumentation.gradle

@@ -94,8 +94,34 @@ configurations {
   runtime.exclude group: 'io.opentelemetry', module: 'opentelemetry-api'
 }
 
+// need to perform shading in two steps in order to avoid shading java.util.logging.Logger
+// in the java-util-logging-events instrumentation since that instrumentation needs to
+// reference unshaded java.util.logging.Logger
+// (java.util.logging.Logger shading is not needed in any of the instrumentation modules,
+// but it is needed for the dependencies, e.g. guava, which use java.util.logging.Logger)
+task shadowJarStep1(type: com.github.jengelman.gradle.plugins.shadow.tasks.ShadowJar) {
+
+  archiveClassifier = 'step1'
+  destinationDirectory = file("${project.buildDir}/step1")
+
+  configurations = [project.configurations.runtime]
+
+  dependencies {
+    exclude(project(':instrumentation:java-util-logging-events'))
+  }
+
+  // rewrite dependencies calling Logger.getLogger
+  relocate 'java.util.logging.Logger', 'io.opentelemetry.auto.bootstrap.PatchLogger'
+}
+
 shadowJar {
 
+  dependsOn shadowJarStep1
+
+  from {
+    zipTree(shadowJarStep1.archiveFile)
+  }
+
   mergeServiceFiles()
 
   exclude '**/module-info.class'
@@ -106,8 +132,6 @@ shadowJar {
 
   // Prevents conflict with other SLF4J instances. Important for premain.
   relocate 'org.slf4j', 'io.opentelemetry.auto.slf4j'
-  // rewrite dependencies calling Logger.getLogger
-  relocate 'java.util.logging.Logger', 'io.opentelemetry.auto.bootstrap.PatchLogger'
 
   dependencies {
     exclude(project(':auto-bootstrap'))

instrumentation/java-util-logging-events/java-util-logging-events.gradle

@@ -0,0 +1 @@
+apply from: "${rootDir}/gradle/java.gradle"

instrumentation/java-util-logging-events/src/main/java/io/opentelemetry/auto/instrumentation/jul/JavaUtilLoggingEventInstrumentation.java

@@ -0,0 +1,61 @@
+package io.opentelemetry.auto.instrumentation.jul;
+
+import static io.opentelemetry.auto.tooling.ByteBuddyElementMatchers.safeHasSuperType;
+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 java.util.logging.LogRecord;
+import java.util.logging.Logger;
+import net.bytebuddy.asm.Advice;
+import net.bytebuddy.description.method.MethodDescription;
+import net.bytebuddy.description.type.TypeDescription;
+import net.bytebuddy.matcher.ElementMatcher;
+
+@AutoService(Instrumenter.class)
+public class JavaUtilLoggingEventInstrumentation extends Instrumenter.Default {
+  public JavaUtilLoggingEventInstrumentation() {
+    super("java-util-logging-events");
+  }
+
+  @Override
+  public ElementMatcher<? super TypeDescription> typeMatcher() {
+    return safeHasSuperType(named("java.util.logging.Logger"));
+  }
+
+  @Override
+  public String[] helperClassNames() {
+    return new String[] {
+      packageName + ".JavaUtilLoggingEvents",
+      packageName + ".JavaUtilLoggingEvents$AccessibleFormatter"
+    };
+  }
+
+  @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("log"))
+            .and(takesArguments(1))
+            .and(takesArgument(0, named("java.util.logging.LogRecord"))),
+        JavaUtilLoggingEventInstrumentation.class.getName() + "$LogMessageAdvice");
+    return transformers;
+  }
+
+  public static class LogMessageAdvice {
+
+    @Advice.OnMethodEnter(suppress = Throwable.class)
+    public static void methodEnter(
+        @Advice.This final Logger logger, @Advice.Argument(0) final LogRecord logRecord) {
+      JavaUtilLoggingEvents.capture(logger, logRecord);
+    }
+  }
+}

instrumentation/java-util-logging-events/src/main/java/io/opentelemetry/auto/instrumentation/jul/JavaUtilLoggingEvents.java

@@ -0,0 +1,104 @@
+package io.opentelemetry.auto.instrumentation.jul;
+
+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 java.util.logging.Formatter;
+import java.util.logging.Level;
+import java.util.logging.LogRecord;
+import java.util.logging.Logger;
+import lombok.extern.slf4j.Slf4j;
+
+@Slf4j
+public class JavaUtilLoggingEvents {
+
+  private static final Tracer TRACER =
+      OpenTelemetry.getTracerFactory().get("io.opentelemetry.auto.java-util-logging-events");
+
+  private static final Formatter FORMATTER = new AccessibleFormatter();
+
+  public static void capture(final Logger logger, final LogRecord logRecord) {
+
+    final Level level = logRecord.getLevel();
+    if (!logger.isLoggable(level)) {
+      // this is already checked in most cases, except if Logger.log(LogRecord) was called directly
+      return;
+    }
+    if (level.intValue() < getThreshold().intValue()) {
+      return;
+    }
+    final Span currentSpan = TRACER.getCurrentSpan();
+    if (!currentSpan.getContext().isValid()) {
+      return;
+    }
+
+    final Throwable t = logRecord.getThrown();
+    final Map<String, AttributeValue> attributes = new HashMap<>(t == null ? 2 : 3);
+    attributes.put("level", newAttributeValue(level.getName()));
+    attributes.put("loggerName", newAttributeValue(logger.getName()));
+    if (t != null) {
+      attributes.put("error.stack", newAttributeValue(toString(t)));
+    }
+    currentSpan.addEvent(FORMATTER.formatMessage(logRecord), 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.SEVERE;
+      case "WARN":
+      case "WARNING":
+        return Level.WARNING;
+      case "INFO":
+        return Level.INFO;
+      case "CONFIG":
+        return Level.CONFIG;
+      case "DEBUG":
+      case "FINE":
+        return Level.FINE;
+      case "FINER":
+        return Level.FINER;
+      case "TRACE":
+      case "FINEST":
+        return Level.FINEST;
+      case "ALL":
+        return Level.ALL;
+      default:
+        log.error("unexpected value for {}: {}", Config.LOGS_EVENTS_THRESHOLD, level);
+        return Level.OFF;
+    }
+  }
+
+  // this is just needed for calling formatMessage in abstract super class
+  public static class AccessibleFormatter extends Formatter {
+
+    @Override
+    public String format(final LogRecord record) {
+      throw new UnsupportedOperationException();
+    }
+  }
+}

instrumentation/java-util-logging-events/src/test/groovy/JavaUtilLoggingEventTest.groovy

@@ -0,0 +1,19 @@
+import io.opentelemetry.auto.test.log.events.LogEventsTestBase
+
+import java.util.logging.Logger
+
+class JavaUtilLoggingEventTest extends LogEventsTestBase {
+
+  @Override
+  Object createLogger(String name) {
+    Logger.getLogger(name)
+  }
+
+  String warn() {
+    return "warning"
+  }
+
+  String error() {
+    return "severe"
+  }
+}

settings.gradle

@@ -88,6 +88,7 @@ include ':instrumentation:java-concurrent:kotlin-testing'
 include ':instrumentation:java-concurrent:scala-testing'
 include ':instrumentation:java-concurrent:akka-testing'
 include ':instrumentation:java-concurrent:akka-2.5-testing'
+include ':instrumentation:java-util-logging-events'
 include ':instrumentation:jdbc'
 include ':instrumentation:jedis-1.4'
 include ':instrumentation:jedis-3.0'

testing/src/main/groovy/io/opentelemetry/auto/test/asserts/EventAssert.groovy

@@ -0,0 +1,42 @@
+package io.opentelemetry.auto.test.asserts
+
+import groovy.transform.stc.ClosureParams
+import groovy.transform.stc.SimpleType
+import io.opentelemetry.sdk.trace.SpanData.TimedEvent
+
+import static TagsAssert.assertTags
+
+class EventAssert {
+  private final TimedEvent event
+  private final checked = [:]
+
+  private EventAssert(event) {
+    this.event = event
+  }
+
+  static void assertEvent(TimedEvent event,
+                          @ClosureParams(value = SimpleType, options = ['io.opentelemetry.auto.test.asserts.EventAssert'])
+                          @DelegatesTo(value = EventAssert, strategy = Closure.DELEGATE_FIRST) Closure spec) {
+    def asserter = new EventAssert(event)
+    asserter.assertEvent spec
+  }
+
+  void assertEvent(
+    @ClosureParams(value = SimpleType, options = ['io.opentelemetry.auto.test.asserts.EventAssert'])
+    @DelegatesTo(value = EventAssert, strategy = Closure.DELEGATE_FIRST) Closure spec) {
+    def clone = (Closure) spec.clone()
+    clone.delegate = this
+    clone.resolveStrategy = Closure.DELEGATE_FIRST
+    clone(this)
+  }
+
+  def name(String name) {
+    assert event.name == name
+    checked.name = true
+  }
+
+  void attributes(@ClosureParams(value = SimpleType, options = ['io.opentelemetry.auto.test.asserts.TagsAssert'])
+                  @DelegatesTo(value = TagsAssert, strategy = Closure.DELEGATE_FIRST) Closure spec) {
+    assertTags(event.attributes, spec)
+  }
+}

testing/src/main/groovy/io/opentelemetry/auto/test/asserts/SpanAssert.groovy

@@ -7,11 +7,14 @@ import io.opentelemetry.trace.Span
 import io.opentelemetry.trace.Status
 
 import static TagsAssert.assertTags
+import static io.opentelemetry.auto.test.asserts.EventAssert.assertEvent
 
 class SpanAssert {
   private final SpanData span
   private final checked = [:]
 
+  private final Set<Integer> assertedEventIndexes = new HashSet<>()
+
   private SpanAssert(span) {
     this.span = span
   }
@@ -21,6 +24,7 @@ class SpanAssert {
                          @DelegatesTo(value = SpanAssert, strategy = Closure.DELEGATE_FIRST) Closure spec) {
     def asserter = new SpanAssert(span)
     asserter.assertSpan spec
+    asserter.assertEventsAllVerified()
   }
 
   void assertSpan(
@@ -33,6 +37,14 @@ class SpanAssert {
     assertDefaults()
   }
 
+  void event(int index, @ClosureParams(value = SimpleType, options = ['io.opentelemetry.auto.test.asserts.EventAssert']) @DelegatesTo(value = EventAssert, strategy = Closure.DELEGATE_FIRST) Closure spec) {
+    if (index >= span.timedEvents.size()) {
+      throw new ArrayIndexOutOfBoundsException(index)
+    }
+    assertedEventIndexes.add(index)
+    assertEvent(span.timedEvents.get(index), spec)
+  }
+
   def assertSpanNameContains(String spanName, String... shouldContainArr) {
     for (String shouldContain : shouldContainArr) {
       assert spanName.contains(shouldContain)
@@ -100,8 +112,12 @@ class SpanAssert {
     }
   }
 
-  void tags(@ClosureParams(value = SimpleType, options = ['io.opentelemetry.auto.test.asserts.AttributesAssert'])
+  void tags(@ClosureParams(value = SimpleType, options = ['io.opentelemetry.auto.test.asserts.TagsAssert'])
             @DelegatesTo(value = TagsAssert, strategy = Closure.DELEGATE_FIRST) Closure spec) {
-    assertTags(span, spec)
+    assertTags(span.attributes, spec)
+  }
+
+  void assertEventsAllVerified() {
+    assert assertedEventIndexes.size() == span.timedEvents.size()
   }
 }

testing/src/main/groovy/io/opentelemetry/auto/test/asserts/TagsAssert.groovy

@@ -2,7 +2,6 @@ package io.opentelemetry.auto.test.asserts
 
 import groovy.transform.stc.ClosureParams
 import groovy.transform.stc.SimpleType
-import io.opentelemetry.sdk.trace.SpanData
 import io.opentelemetry.trace.AttributeValue
 
 import java.util.regex.Pattern
@@ -11,14 +10,14 @@ class TagsAssert {
   private final Map<String, AttributeValue> tags
   private final Set<String> assertedTags = new TreeSet<>()
 
-  private TagsAssert(SpanData span) {
+  private TagsAssert(attributes) {
-    this.tags = span.attributes
+    this.tags = attributes
   }
 
-  static void assertTags(SpanData span,
+  static void assertTags(Map<String, AttributeValue> attributes,
                          @ClosureParams(value = SimpleType, options = ['io.opentelemetry.auto.test.asserts.TagsAssert'])
                          @DelegatesTo(value = TagsAssert, strategy = Closure.DELEGATE_FIRST) Closure spec) {
-    def asserter = new TagsAssert(span)
+    def asserter = new TagsAssert(attributes)
     def clone = (Closure) spec.clone()
     clone.delegate = asserter
     clone.resolveStrategy = Closure.DELEGATE_FIRST

testing/src/main/groovy/io/opentelemetry/auto/test/log/events/LogEventsTestBase.groovy

@@ -0,0 +1,69 @@
+package io.opentelemetry.auto.test.log.events
+
+import io.opentelemetry.OpenTelemetry
+import io.opentelemetry.auto.config.Config
+import io.opentelemetry.auto.test.AgentTestRunner
+import io.opentelemetry.trace.Tracer
+import spock.lang.Unroll
+
+import static io.opentelemetry.auto.test.utils.ConfigUtils.withConfigOverride
+
+/**
+ * This class represents the standard test cases that new logging library integrations MUST
+ * satisfy in order to support log events.
+ */
+@Unroll
+abstract class LogEventsTestBase extends AgentTestRunner {
+
+  final Tracer tracer = OpenTelemetry.getTracerFactory().get("io.opentelemetry.auto.test")
+
+  abstract Object createLogger(String name)
+
+  String warn() {
+    return "warn"
+  }
+
+  String error() {
+    return "error"
+  }
+
+  def "capture #testMethod (#capture)"() {
+    setup:
+    def parentSpan = tracer.spanBuilder("test").startSpan()
+    def parentScope = tracer.withSpan(parentSpan)
+
+    def logger = createLogger("abc")
+    withConfigOverride(Config.LOGS_EVENTS_THRESHOLD, "WARN") {
+      logger."$testMethod"("xyz")
+    }
+
+    parentSpan.end()
+    parentScope.close()
+
+    expect:
+    assertTraces(1) {
+      trace(0, 1) {
+        span(0) {
+          operationName "test"
+          if (capture) {
+            event(0) {
+              name "xyz"
+              attributes {
+                "level" testMethod.toUpperCase()
+                "loggerName" "abc"
+              }
+            }
+          }
+          tags {
+          }
+        }
+      }
+    }
+
+    where:
+    testMethod | capture
+    "info"     | false
+    warn()     | true
+    error()    | true
+  }
+}