Capture java util logging events
* 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
MODIFY
agent-bootstrap/src/main/java/io/opentelemetry/auto/config/Config.java
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);

MODIFY
instrumentation/instrumentation.gradle
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'))

ADD
instrumentation/java-util-logging-events/java-util-logging-events.gradle
+apply from: "${rootDir}/gradle/java.gradle"

ADD
instrumentation/java-util-logging-events/src/main/java/io/opentelemetry/auto/instrumentation/jul/JavaUtilLoggingEventInstrumentation.java
+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);
+ }
+ }
+}

ADD
instrumentation/java-util-logging-events/src/main/java/io/opentelemetry/auto/instrumentation/jul/JavaUtilLoggingEvents.java
+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();
+ }
+ }
+}

ADD
instrumentation/java-util-logging-events/src/test/groovy/JavaUtilLoggingEventTest.groovy
+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"
+ }
+}

MODIFY
settings.gradle
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'

ADD
testing/src/main/groovy/io/opentelemetry/auto/test/asserts/EventAssert.groovy
+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)
+ }
+}

MODIFY
testing/src/main/groovy/io/opentelemetry/auto/test/asserts/SpanAssert.groovy
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()
}
}

MODIFY
testing/src/main/groovy/io/opentelemetry/auto/test/asserts/TagsAssert.groovy
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) {
- this.tags = span.attributes
+ private TagsAssert(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

ADD
testing/src/main/groovy/io/opentelemetry/auto/test/log/events/LogEventsTestBase.groovy
+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
+ }
+}

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