From 47aacd3318908688da13f208c7bcec9f26b7e156 Mon Sep 17 00:00:00 2001 From: Trask Stalnaker Date: Mon, 20 Dec 2021 12:36:30 -0800 Subject: [PATCH] Add java.util.logging javaagent instrumentation (#4941) * java.util.logging * Update instrumentation/java-util-logging/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/jul/JavaUtilLoggingInstrumentationModule.java * sync * Update instrumentation/java-util-logging/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/jul/JavaUtilLoggingHelper.java Co-authored-by: Anuraag Agrawal * Remove unused code * Simplification * Remove JBoss logger instrumentation * Spotless * Unroll * Remove unused dependency Co-authored-by: Anuraag Agrawal --- ...rumentation.javaagent-shadowing.gradle.kts | 3 + .../javaagent/build.gradle.kts | 11 ++ .../jul/JavaUtilLoggingHelper.java | 126 ++++++++++++++++++ .../jul/JavaUtilLoggingInstrumentation.java | 64 +++++++++ .../JavaUtilLoggingInstrumentationModule.java | 26 ++++ .../test/groovy/JavaUtilLoggingTest.groovy | 92 +++++++++++++ .../build.gradle.kts | 3 + .../application/java/util/logging/Logger.java | 18 +++ settings.gradle.kts | 2 + 9 files changed, 345 insertions(+) create mode 100644 instrumentation/java-util-logging/javaagent/build.gradle.kts create mode 100644 instrumentation/java-util-logging/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/jul/JavaUtilLoggingHelper.java create mode 100644 instrumentation/java-util-logging/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/jul/JavaUtilLoggingInstrumentation.java create mode 100644 instrumentation/java-util-logging/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/jul/JavaUtilLoggingInstrumentationModule.java create mode 100644 instrumentation/java-util-logging/javaagent/src/test/groovy/JavaUtilLoggingTest.groovy create mode 100644 instrumentation/java-util-logging/shaded-stub-for-instrumenting/build.gradle.kts create mode 100644 instrumentation/java-util-logging/shaded-stub-for-instrumenting/src/main/java/application/java/util/logging/Logger.java diff --git a/gradle-plugins/src/main/kotlin/io.opentelemetry.instrumentation.javaagent-shadowing.gradle.kts b/gradle-plugins/src/main/kotlin/io.opentelemetry.instrumentation.javaagent-shadowing.gradle.kts index 0d05b5bc65..8bb542128e 100644 --- a/gradle-plugins/src/main/kotlin/io.opentelemetry.instrumentation.javaagent-shadowing.gradle.kts +++ b/gradle-plugins/src/main/kotlin/io.opentelemetry.instrumentation.javaagent-shadowing.gradle.kts @@ -33,4 +33,7 @@ tasks.withType().configureEach { // this is for instrumentation on opentelemetry-api itself relocate("application.io.opentelemetry", "io.opentelemetry") + + // this is for instrumentation on java.util.logging (since java.util.logging itself is shaded above) + relocate("application.java.util.logging", "java.util.logging") } diff --git a/instrumentation/java-util-logging/javaagent/build.gradle.kts b/instrumentation/java-util-logging/javaagent/build.gradle.kts new file mode 100644 index 0000000000..1c82780202 --- /dev/null +++ b/instrumentation/java-util-logging/javaagent/build.gradle.kts @@ -0,0 +1,11 @@ +plugins { + id("otel.javaagent-instrumentation") +} + +dependencies { + compileOnly(project(":instrumentation:java-util-logging:shaded-stub-for-instrumenting")) + + compileOnly(project(":instrumentation-api-appender")) + + testImplementation("org.awaitility:awaitility") +} diff --git a/instrumentation/java-util-logging/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/jul/JavaUtilLoggingHelper.java b/instrumentation/java-util-logging/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/jul/JavaUtilLoggingHelper.java new file mode 100644 index 0000000000..6b4acc33e8 --- /dev/null +++ b/instrumentation/java-util-logging/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/jul/JavaUtilLoggingHelper.java @@ -0,0 +1,126 @@ +/* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ + +package io.opentelemetry.javaagent.instrumentation.jul; + +import application.java.util.logging.Logger; +import io.opentelemetry.api.common.Attributes; +import io.opentelemetry.api.common.AttributesBuilder; +import io.opentelemetry.context.Context; +import io.opentelemetry.instrumentation.api.appender.GlobalLogEmitterProvider; +import io.opentelemetry.instrumentation.api.appender.LogBuilder; +import io.opentelemetry.instrumentation.api.appender.Severity; +import io.opentelemetry.semconv.trace.attributes.SemanticAttributes; +import java.io.PrintWriter; +import java.io.StringWriter; +import java.util.concurrent.TimeUnit; +import java.util.logging.Formatter; +import java.util.logging.Level; +import java.util.logging.LogRecord; + +public final class JavaUtilLoggingHelper { + + private static final Formatter FORMATTER = new AccessibleFormatter(); + + public static void capture(Logger logger, LogRecord logRecord) { + + if (!logger.isLoggable(logRecord.getLevel())) { + // this is already checked in most cases, except if Logger.log(LogRecord) was called directly + return; + } + + LogBuilder builder = + GlobalLogEmitterProvider.get() + .logEmitterBuilder(logRecord.getLoggerName()) + .build() + .logBuilder(); + mapLogRecord(builder, logRecord); + builder.emit(); + } + + /** + * Map the {@link LogRecord} data model onto the {@link LogBuilder}. Unmapped fields include: + * + *
    + *
  • Fully qualified class name - {@link LogRecord#getSourceClassName()} + *
  • Fully qualified method name - {@link LogRecord#getSourceMethodName()} + *
  • Thread id - {@link LogRecord#getThreadID()} + *
+ */ + private static void mapLogRecord(LogBuilder builder, LogRecord logRecord) { + // message + String message = FORMATTER.formatMessage(logRecord); + if (message != null) { + builder.setBody(message); + } + + // time + // TODO (trask) use getInstant() for more precision on Java 9 + long timestamp = logRecord.getMillis(); + builder.setEpoch(timestamp, TimeUnit.MILLISECONDS); + + // level + Level level = logRecord.getLevel(); + if (level != null) { + builder.setSeverity(levelToSeverity(level)); + builder.setSeverityText(logRecord.getLevel().getName()); + } + + // throwable + Throwable throwable = logRecord.getThrown(); + if (throwable != null) { + AttributesBuilder attributes = Attributes.builder(); + + // TODO (trask) extract method for recording exception into instrumentation-api-appender + attributes.put(SemanticAttributes.EXCEPTION_TYPE, throwable.getClass().getName()); + attributes.put(SemanticAttributes.EXCEPTION_MESSAGE, throwable.getMessage()); + StringWriter writer = new StringWriter(); + throwable.printStackTrace(new PrintWriter(writer)); + attributes.put(SemanticAttributes.EXCEPTION_STACKTRACE, writer.toString()); + + builder.setAttributes(attributes.build()); + } + + // span context + builder.setContext(Context.current()); + } + + private static Severity levelToSeverity(Level level) { + int lev = level.intValue(); + if (lev <= Level.FINEST.intValue()) { + return Severity.TRACE; + } + if (lev <= Level.FINER.intValue()) { + return Severity.DEBUG; + } + if (lev <= Level.FINE.intValue()) { + return Severity.DEBUG2; + } + if (lev <= Level.CONFIG.intValue()) { + return Severity.DEBUG3; + } + if (lev <= Level.INFO.intValue()) { + return Severity.INFO; + } + if (lev <= Level.WARNING.intValue()) { + return Severity.WARN; + } + if (lev <= Level.SEVERE.intValue()) { + return Severity.ERROR; + } + return Severity.FATAL; + } + + // this is just needed for calling formatMessage in abstract super class + private static class AccessibleFormatter extends Formatter { + + @Override + public String format(final LogRecord record) { + throw new UnsupportedOperationException(); + } + } + + private JavaUtilLoggingHelper() {} +} diff --git a/instrumentation/java-util-logging/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/jul/JavaUtilLoggingInstrumentation.java b/instrumentation/java-util-logging/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/jul/JavaUtilLoggingInstrumentation.java new file mode 100644 index 0000000000..ac3c3d73d3 --- /dev/null +++ b/instrumentation/java-util-logging/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/jul/JavaUtilLoggingInstrumentation.java @@ -0,0 +1,64 @@ +/* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ + +package io.opentelemetry.javaagent.instrumentation.jul; + +import static io.opentelemetry.javaagent.extension.matcher.AgentElementMatchers.extendsClass; +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 application.java.util.logging.Logger; +import io.opentelemetry.instrumentation.api.appender.LogEmitterProvider; +import io.opentelemetry.javaagent.extension.instrumentation.TypeInstrumentation; +import io.opentelemetry.javaagent.extension.instrumentation.TypeTransformer; +import io.opentelemetry.javaagent.instrumentation.api.CallDepth; +import java.util.logging.LogRecord; +import net.bytebuddy.asm.Advice; +import net.bytebuddy.description.type.TypeDescription; +import net.bytebuddy.matcher.ElementMatcher; + +class JavaUtilLoggingInstrumentation implements TypeInstrumentation { + + @Override + public ElementMatcher typeMatcher() { + return extendsClass(named("application.java.util.logging.Logger")); + } + + @Override + public void transform(TypeTransformer transformer) { + transformer.applyAdviceToMethod( + isMethod() + .and(isPublic()) + .and(named("log")) + .and(takesArguments(1)) + .and(takesArgument(0, named("java.util.logging.LogRecord"))), + JavaUtilLoggingInstrumentation.class.getName() + "$LogAdvice"); + } + + @SuppressWarnings("unused") + public static class LogAdvice { + + @Advice.OnMethodEnter(suppress = Throwable.class) + public static void methodEnter( + @Advice.This final Logger logger, + @Advice.Argument(0) final LogRecord logRecord, + @Advice.Local("otelCallDepth") CallDepth callDepth) { + // need to track call depth across all loggers in order to avoid double capture when one + // logging framework delegates to another + callDepth = CallDepth.forClass(LogEmitterProvider.class); + if (callDepth.getAndIncrement() == 0) { + JavaUtilLoggingHelper.capture(logger, logRecord); + } + } + + @Advice.OnMethodExit(onThrowable = Throwable.class, suppress = Throwable.class) + public static void methodExit(@Advice.Local("otelCallDepth") CallDepth callDepth) { + callDepth.decrementAndGet(); + } + } +} diff --git a/instrumentation/java-util-logging/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/jul/JavaUtilLoggingInstrumentationModule.java b/instrumentation/java-util-logging/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/jul/JavaUtilLoggingInstrumentationModule.java new file mode 100644 index 0000000000..b5e69f36c2 --- /dev/null +++ b/instrumentation/java-util-logging/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/jul/JavaUtilLoggingInstrumentationModule.java @@ -0,0 +1,26 @@ +/* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ + +package io.opentelemetry.javaagent.instrumentation.jul; + +import static java.util.Collections.singletonList; + +import com.google.auto.service.AutoService; +import io.opentelemetry.javaagent.extension.instrumentation.InstrumentationModule; +import io.opentelemetry.javaagent.extension.instrumentation.TypeInstrumentation; +import java.util.List; + +@AutoService(InstrumentationModule.class) +public class JavaUtilLoggingInstrumentationModule extends InstrumentationModule { + + public JavaUtilLoggingInstrumentationModule() { + super("java-util-logging"); + } + + @Override + public List typeInstrumentations() { + return singletonList(new JavaUtilLoggingInstrumentation()); + } +} diff --git a/instrumentation/java-util-logging/javaagent/src/test/groovy/JavaUtilLoggingTest.groovy b/instrumentation/java-util-logging/javaagent/src/test/groovy/JavaUtilLoggingTest.groovy new file mode 100644 index 0000000000..0c667fd062 --- /dev/null +++ b/instrumentation/java-util-logging/javaagent/src/test/groovy/JavaUtilLoggingTest.groovy @@ -0,0 +1,92 @@ +/* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ + +import io.opentelemetry.instrumentation.test.AgentInstrumentationSpecification +import io.opentelemetry.sdk.logs.data.Severity +import io.opentelemetry.semconv.trace.attributes.SemanticAttributes +import spock.lang.Unroll + +import java.util.logging.Level +import java.util.logging.Logger + +import static io.opentelemetry.instrumentation.test.utils.TraceUtils.runUnderTrace +import static org.assertj.core.api.Assertions.assertThat +import static org.awaitility.Awaitility.await + +class JavaUtilLoggingTest extends AgentInstrumentationSpecification { + + private static final Logger logger = Logger.getLogger("abc") + + @Unroll + def "test method=#testMethod with exception=#exception and parent=#parent"() { + when: + if (parent) { + runUnderTrace("parent") { + if (exception) { + logger.log(Level."${testMethod.toUpperCase()}", "xyz", new IllegalStateException("hello")) + } else { + logger."$testMethod"("xyz") + } + } + } else { + if (exception) { + logger.log(Level."${testMethod.toUpperCase()}", "xyz", new IllegalStateException("hello")) + } else { + logger."$testMethod"("xyz") + } + } + + then: + if (parent) { + waitForTraces(1) + } + + if (severity != null) { + await() + .untilAsserted( + () -> { + assertThat(logs).hasSize(1) + }) + def log = logs.get(0) + assertThat(log.getBody().asString()).isEqualTo("xyz") + assertThat(log.getInstrumentationLibraryInfo().getName()).isEqualTo("abc") + assertThat(log.getSeverity()).isEqualTo(severity) + assertThat(log.getSeverityText()).isEqualTo(severityText) + if (exception) { + assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_TYPE)).isEqualTo(IllegalStateException.class.getName()) + assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_MESSAGE)).isEqualTo("hello") + assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_STACKTRACE)).contains(JavaUtilLoggingTest.name) + } else { + assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_TYPE)).isNull() + assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_MESSAGE)).isNull() + assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_STACKTRACE)).isNull() + } + if (parent) { + assertThat(log.getSpanContext()).isEqualTo(traces.get(0).get(0).getSpanContext()) + } else { + assertThat(log.getSpanContext().isValid()).isFalse() + } + } else { + Thread.sleep(500) // sleep a bit just to make sure no log is captured + logs.size() == 0 + } + + where: + [args, exception, parent] << [ + [ + ["fine", null, null], + ["info", Severity.INFO, "INFO"], + ["warning", Severity.WARN, "WARNING"], + ["severe", Severity.ERROR, "SEVERE"] + ], + [true, false], + [true, false] + ].combinations() + + testMethod = args[0] + severity = args[1] + severityText = args[2] + } +} diff --git a/instrumentation/java-util-logging/shaded-stub-for-instrumenting/build.gradle.kts b/instrumentation/java-util-logging/shaded-stub-for-instrumenting/build.gradle.kts new file mode 100644 index 0000000000..0a3932d242 --- /dev/null +++ b/instrumentation/java-util-logging/shaded-stub-for-instrumenting/build.gradle.kts @@ -0,0 +1,3 @@ +plugins { + id("otel.java-conventions") +} diff --git a/instrumentation/java-util-logging/shaded-stub-for-instrumenting/src/main/java/application/java/util/logging/Logger.java b/instrumentation/java-util-logging/shaded-stub-for-instrumenting/src/main/java/application/java/util/logging/Logger.java new file mode 100644 index 0000000000..0a57455653 --- /dev/null +++ b/instrumentation/java-util-logging/shaded-stub-for-instrumenting/src/main/java/application/java/util/logging/Logger.java @@ -0,0 +1,18 @@ +/* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ + +package application.java.util.logging; + +import java.util.logging.Level; + +// java.util.logging.Logger shaded so that it can be used in instrumentation +// of java.util.logging.Logger itself, and then its usage can be unshaded +// after java.util.logging.Logger is shaded to the "PatchLogger" +public class Logger { + + public boolean isLoggable(@SuppressWarnings("unused") Level level) { + throw new UnsupportedOperationException(); + } +} diff --git a/settings.gradle.kts b/settings.gradle.kts index 0c5ec9d937..476e0d21e4 100644 --- a/settings.gradle.kts +++ b/settings.gradle.kts @@ -199,6 +199,8 @@ include(":instrumentation:hibernate:hibernate-procedure-call-4.3:javaagent") include(":instrumentation:http-url-connection:javaagent") include(":instrumentation:hystrix-1.4:javaagent") include(":instrumentation:java-http-client:javaagent") +include(":instrumentation:java-util-logging:javaagent") +include(":instrumentation:java-util-logging:shaded-stub-for-instrumenting") include(":instrumentation:jaxrs:jaxrs-common:bootstrap") include(":instrumentation:jaxrs:jaxrs-1.0:javaagent") include(":instrumentation:jaxrs:jaxrs-2.0:jaxrs-2.0-arquillian-testing")