From da7dc5412e28c396b37cc3a2f67a0aa99bebb1bd Mon Sep 17 00:00:00 2001 From: Trask Stalnaker Date: Mon, 24 Feb 2020 12:03:34 -0800 Subject: [PATCH] Capture Log4j 2.x events (#182) --- .../log4j-events-2.0/log4j-events-2.0.gradle | 41 +++++++++ .../v2_0/Log4jEventInstrumentation.java | 92 +++++++++++++++++++ .../log4jevents/v2_0/Log4jEvents.java | 86 +++++++++++++++++ .../src/test/groovy/Log4jEventTest.groovy | 16 ++++ .../src/test/resources/log4j2.xml | 14 +++ settings.gradle | 1 + 6 files changed, 250 insertions(+) create mode 100644 instrumentation/log4j-events-2.0/log4j-events-2.0.gradle create mode 100644 instrumentation/log4j-events-2.0/src/main/java/io/opentelemetry/auto/instrumentation/log4jevents/v2_0/Log4jEventInstrumentation.java create mode 100644 instrumentation/log4j-events-2.0/src/main/java/io/opentelemetry/auto/instrumentation/log4jevents/v2_0/Log4jEvents.java create mode 100644 instrumentation/log4j-events-2.0/src/test/groovy/Log4jEventTest.groovy create mode 100644 instrumentation/log4j-events-2.0/src/test/resources/log4j2.xml diff --git a/instrumentation/log4j-events-2.0/log4j-events-2.0.gradle b/instrumentation/log4j-events-2.0/log4j-events-2.0.gradle new file mode 100644 index 0000000000..a3ae5d690e --- /dev/null +++ b/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: '+' +} diff --git a/instrumentation/log4j-events-2.0/src/main/java/io/opentelemetry/auto/instrumentation/log4jevents/v2_0/Log4jEventInstrumentation.java b/instrumentation/log4j-events-2.0/src/main/java/io/opentelemetry/auto/instrumentation/log4jevents/v2_0/Log4jEventInstrumentation.java new file mode 100644 index 0000000000..8b47174106 --- /dev/null +++ b/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 typeMatcher() { + return safeHasSuperType(named("org.apache.logging.log4j.spi.AbstractLogger")); + } + + @Override + public String[] helperClassNames() { + return new String[] {packageName + ".Log4jEvents"}; + } + + @Override + public Map, String> transformers() { + final Map, 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); + } + } +} diff --git a/instrumentation/log4j-events-2.0/src/main/java/io/opentelemetry/auto/instrumentation/log4jevents/v2_0/Log4jEvents.java b/instrumentation/log4j-events-2.0/src/main/java/io/opentelemetry/auto/instrumentation/log4jevents/v2_0/Log4jEvents.java new file mode 100644 index 0000000000..306f7040a2 --- /dev/null +++ b/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 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; + } + } +} diff --git a/instrumentation/log4j-events-2.0/src/test/groovy/Log4jEventTest.groovy b/instrumentation/log4j-events-2.0/src/test/groovy/Log4jEventTest.groovy new file mode 100644 index 0000000000..e626342e05 --- /dev/null +++ b/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) + } +} diff --git a/instrumentation/log4j-events-2.0/src/test/resources/log4j2.xml b/instrumentation/log4j-events-2.0/src/test/resources/log4j2.xml new file mode 100644 index 0000000000..297a6752dd --- /dev/null +++ b/instrumentation/log4j-events-2.0/src/test/resources/log4j2.xml @@ -0,0 +1,14 @@ + + + + + + + + + + + + + + diff --git a/settings.gradle b/settings.gradle index 304bb8b3a9..42f568001c 100644 --- a/settings.gradle +++ b/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'