From 0f98f41d1c5010f02fdc30a9fe977e0750f2aefc Mon Sep 17 00:00:00 2001 From: Trask Stalnaker Date: Thu, 20 Feb 2020 14:29:36 -0800 Subject: [PATCH] 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 --- .../io/opentelemetry/auto/config/Config.java | 25 ++++- instrumentation/instrumentation.gradle | 28 ++++- .../java-util-logging-events.gradle | 1 + .../JavaUtilLoggingEventInstrumentation.java | 61 ++++++++++ .../jul/JavaUtilLoggingEvents.java | 104 ++++++++++++++++++ .../groovy/JavaUtilLoggingEventTest.groovy | 19 ++++ settings.gradle | 1 + .../auto/test/asserts/EventAssert.groovy | 42 +++++++ .../auto/test/asserts/SpanAssert.groovy | 20 +++- .../auto/test/asserts/TagsAssert.groovy | 9 +- .../test/log/events/LogEventsTestBase.groovy | 69 ++++++++++++ 11 files changed, 368 insertions(+), 11 deletions(-) create mode 100644 instrumentation/java-util-logging-events/java-util-logging-events.gradle create mode 100644 instrumentation/java-util-logging-events/src/main/java/io/opentelemetry/auto/instrumentation/jul/JavaUtilLoggingEventInstrumentation.java create mode 100644 instrumentation/java-util-logging-events/src/main/java/io/opentelemetry/auto/instrumentation/jul/JavaUtilLoggingEvents.java create mode 100644 instrumentation/java-util-logging-events/src/test/groovy/JavaUtilLoggingEventTest.groovy create mode 100644 testing/src/main/groovy/io/opentelemetry/auto/test/asserts/EventAssert.groovy create mode 100644 testing/src/main/groovy/io/opentelemetry/auto/test/log/events/LogEventsTestBase.groovy diff --git a/agent-bootstrap/src/main/java/io/opentelemetry/auto/config/Config.java b/agent-bootstrap/src/main/java/io/opentelemetry/auto/config/Config.java index d30ea1fb3c..0f993e1064 100644 --- a/agent-bootstrap/src/main/java/io/opentelemetry/auto/config/Config.java +++ b/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); diff --git a/instrumentation/instrumentation.gradle b/instrumentation/instrumentation.gradle index 26e8087bd4..ab4d6014dc 100644 --- a/instrumentation/instrumentation.gradle +++ b/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')) diff --git a/instrumentation/java-util-logging-events/java-util-logging-events.gradle b/instrumentation/java-util-logging-events/java-util-logging-events.gradle new file mode 100644 index 0000000000..ff6901ae6f --- /dev/null +++ b/instrumentation/java-util-logging-events/java-util-logging-events.gradle @@ -0,0 +1 @@ +apply from: "${rootDir}/gradle/java.gradle" diff --git a/instrumentation/java-util-logging-events/src/main/java/io/opentelemetry/auto/instrumentation/jul/JavaUtilLoggingEventInstrumentation.java b/instrumentation/java-util-logging-events/src/main/java/io/opentelemetry/auto/instrumentation/jul/JavaUtilLoggingEventInstrumentation.java new file mode 100644 index 0000000000..e7fea6e115 --- /dev/null +++ b/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 typeMatcher() { + return safeHasSuperType(named("java.util.logging.Logger")); + } + + @Override + public String[] helperClassNames() { + return new String[] { + packageName + ".JavaUtilLoggingEvents", + packageName + ".JavaUtilLoggingEvents$AccessibleFormatter" + }; + } + + @Override + public Map, String> transformers() { + final Map, 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); + } + } +} diff --git a/instrumentation/java-util-logging-events/src/main/java/io/opentelemetry/auto/instrumentation/jul/JavaUtilLoggingEvents.java b/instrumentation/java-util-logging-events/src/main/java/io/opentelemetry/auto/instrumentation/jul/JavaUtilLoggingEvents.java new file mode 100644 index 0000000000..3e6bf4d6ff --- /dev/null +++ b/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 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(); + } + } +} diff --git a/instrumentation/java-util-logging-events/src/test/groovy/JavaUtilLoggingEventTest.groovy b/instrumentation/java-util-logging-events/src/test/groovy/JavaUtilLoggingEventTest.groovy new file mode 100644 index 0000000000..90df6fbac2 --- /dev/null +++ b/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" + } +} diff --git a/settings.gradle b/settings.gradle index 8b20222fea..d3c43bdbef 100644 --- a/settings.gradle +++ b/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' diff --git a/testing/src/main/groovy/io/opentelemetry/auto/test/asserts/EventAssert.groovy b/testing/src/main/groovy/io/opentelemetry/auto/test/asserts/EventAssert.groovy new file mode 100644 index 0000000000..73e700ca66 --- /dev/null +++ b/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) + } +} diff --git a/testing/src/main/groovy/io/opentelemetry/auto/test/asserts/SpanAssert.groovy b/testing/src/main/groovy/io/opentelemetry/auto/test/asserts/SpanAssert.groovy index a78efe1b13..c26e10e4bb 100644 --- a/testing/src/main/groovy/io/opentelemetry/auto/test/asserts/SpanAssert.groovy +++ b/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 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() } } diff --git a/testing/src/main/groovy/io/opentelemetry/auto/test/asserts/TagsAssert.groovy b/testing/src/main/groovy/io/opentelemetry/auto/test/asserts/TagsAssert.groovy index 748ac47113..925da23f54 100644 --- a/testing/src/main/groovy/io/opentelemetry/auto/test/asserts/TagsAssert.groovy +++ b/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 tags private final Set 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 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 diff --git a/testing/src/main/groovy/io/opentelemetry/auto/test/log/events/LogEventsTestBase.groovy b/testing/src/main/groovy/io/opentelemetry/auto/test/log/events/LogEventsTestBase.groovy new file mode 100644 index 0000000000..eb54e4c7fe --- /dev/null +++ b/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 + } +}