From 1f8ae0c00d521f147f0eef1a4caec54df4d0a098 Mon Sep 17 00:00:00 2001 From: Trask Stalnaker Date: Mon, 3 Jan 2022 10:32:49 -0800 Subject: [PATCH] Add support for capturing logback mdc attributes (#4968) * Add support for capturing logback mdc attributes * Spotless --- .../javaagent/build.gradle.kts | 7 + .../logback/appender/v1_0/LogbackHelper.java | 106 ------------ .../appender/v1_0/LogbackInstrumentation.java | 3 +- .../src/test/groovy/LogbackTest.groovy | 29 ++++ .../library/build.gradle.kts | 20 +++ .../v1_0/internal/LoggingEventMapper.java | 163 ++++++++++++++++++ .../v1_0/internal/LoggingEventMapperTest.java | 73 ++++++++ settings.gradle.kts | 1 + 8 files changed, 295 insertions(+), 107 deletions(-) delete mode 100644 instrumentation/logback/logback-appender-1.0/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/logback/appender/v1_0/LogbackHelper.java create mode 100644 instrumentation/logback/logback-appender-1.0/library/build.gradle.kts create mode 100644 instrumentation/logback/logback-appender-1.0/library/src/main/java/io/opentelemetry/instrumentation/logback/appender/v1_0/internal/LoggingEventMapper.java create mode 100644 instrumentation/logback/logback-appender-1.0/library/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/internal/LoggingEventMapperTest.java diff --git a/instrumentation/logback/logback-appender-1.0/javaagent/build.gradle.kts b/instrumentation/logback/logback-appender-1.0/javaagent/build.gradle.kts index d240fb83fedb..62d5e90aa0e3 100644 --- a/instrumentation/logback/logback-appender-1.0/javaagent/build.gradle.kts +++ b/instrumentation/logback/logback-appender-1.0/javaagent/build.gradle.kts @@ -19,7 +19,14 @@ dependencies { compileOnly(project(":instrumentation-api-appender")) + implementation(project(":instrumentation:logback:logback-appender-1.0:library")) + latestDepTestLibrary("ch.qos.logback:logback-classic:1.2.+") testImplementation("org.awaitility:awaitility") } + +tasks.withType().configureEach { + // TODO run tests both with and without experimental log attributes + jvmArgs("-Dotel.instrumentation.logback-appender.experimental.capture-mdc-attributes=*") +} diff --git a/instrumentation/logback/logback-appender-1.0/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/logback/appender/v1_0/LogbackHelper.java b/instrumentation/logback/logback-appender-1.0/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/logback/appender/v1_0/LogbackHelper.java deleted file mode 100644 index 7d61253cd0f4..000000000000 --- a/instrumentation/logback/logback-appender-1.0/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/logback/appender/v1_0/LogbackHelper.java +++ /dev/null @@ -1,106 +0,0 @@ -/* - * Copyright The OpenTelemetry Authors - * SPDX-License-Identifier: Apache-2.0 - */ - -package io.opentelemetry.javaagent.instrumentation.logback.appender.v1_0; - -import ch.qos.logback.classic.Level; -import ch.qos.logback.classic.spi.ILoggingEvent; -import ch.qos.logback.classic.spi.ThrowableProxy; -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; - -public final class LogbackHelper { - - public static void capture(final ILoggingEvent event) { - LogBuilder builder = - GlobalLogEmitterProvider.get() - .logEmitterBuilder(event.getLoggerName()) - .build() - .logBuilder(); - mapLoggingEvent(builder, event); - builder.emit(); - } - - /** - * Map the {@link ILoggingEvent} data model onto the {@link LogBuilder}. Unmapped fields include: - * - * - */ - private static void mapLoggingEvent(LogBuilder builder, ILoggingEvent loggingEvent) { - // message - String message = loggingEvent.getMessage(); - if (message != null) { - builder.setBody(message); - } - - // time - long timestamp = loggingEvent.getTimeStamp(); - builder.setEpoch(timestamp, TimeUnit.MILLISECONDS); - - // level - Level level = loggingEvent.getLevel(); - if (level != null) { - builder.setSeverity(levelToSeverity(level)); - builder.setSeverityText(level.levelStr); - } - - // throwable - Object throwableProxy = loggingEvent.getThrowableProxy(); - Throwable throwable = null; - if (throwableProxy instanceof ThrowableProxy) { - // there is only one other subclass of ch.qos.logback.classic.spi.IThrowableProxy - // and it is only used for logging exceptions over the wire - throwable = ((ThrowableProxy) throwableProxy).getThrowable(); - } - 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) { - switch (level.levelInt) { - case Level.ALL_INT: - case Level.TRACE_INT: - return Severity.TRACE; - case Level.DEBUG_INT: - return Severity.DEBUG; - case Level.INFO_INT: - return Severity.INFO; - case Level.WARN_INT: - return Severity.WARN; - case Level.ERROR_INT: - return Severity.ERROR; - case Level.OFF_INT: - default: - return Severity.UNDEFINED_SEVERITY_NUMBER; - } - } - - private LogbackHelper() {} -} diff --git a/instrumentation/logback/logback-appender-1.0/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/logback/appender/v1_0/LogbackInstrumentation.java b/instrumentation/logback/logback-appender-1.0/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/logback/appender/v1_0/LogbackInstrumentation.java index e38664d3042f..0e44c6e876e9 100644 --- a/instrumentation/logback/logback-appender-1.0/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/logback/appender/v1_0/LogbackInstrumentation.java +++ b/instrumentation/logback/logback-appender-1.0/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/logback/appender/v1_0/LogbackInstrumentation.java @@ -13,6 +13,7 @@ import ch.qos.logback.classic.spi.ILoggingEvent; import io.opentelemetry.instrumentation.api.appender.LogEmitterProvider; +import io.opentelemetry.instrumentation.logback.appender.v1_0.internal.LoggingEventMapper; import io.opentelemetry.javaagent.extension.instrumentation.TypeInstrumentation; import io.opentelemetry.javaagent.extension.instrumentation.TypeTransformer; import io.opentelemetry.javaagent.instrumentation.api.CallDepth; @@ -49,7 +50,7 @@ public static void methodEnter( // logging framework delegates to another callDepth = CallDepth.forClass(LogEmitterProvider.class); if (callDepth.getAndIncrement() == 0) { - LogbackHelper.capture(event); + LoggingEventMapper.INSTANCE.capture(event); } } diff --git a/instrumentation/logback/logback-appender-1.0/javaagent/src/test/groovy/LogbackTest.groovy b/instrumentation/logback/logback-appender-1.0/javaagent/src/test/groovy/LogbackTest.groovy index 4ffedf37c4f8..a854ee5c958a 100644 --- a/instrumentation/logback/logback-appender-1.0/javaagent/src/test/groovy/LogbackTest.groovy +++ b/instrumentation/logback/logback-appender-1.0/javaagent/src/test/groovy/LogbackTest.groovy @@ -3,11 +3,13 @@ * SPDX-License-Identifier: Apache-2.0 */ +import io.opentelemetry.api.common.AttributeKey import io.opentelemetry.instrumentation.test.AgentInstrumentationSpecification import io.opentelemetry.sdk.logs.data.Severity import io.opentelemetry.semconv.trace.attributes.SemanticAttributes import org.slf4j.Logger import org.slf4j.LoggerFactory +import org.slf4j.MDC import spock.lang.Unroll import static io.opentelemetry.instrumentation.test.utils.TraceUtils.runUnderTrace @@ -95,4 +97,31 @@ class LogbackTest extends AgentInstrumentationSpecification { severity = args[3] severityText = args[4] } + + def "test mdc"() { + when: + MDC.put("key1", "val1") + MDC.put("key2", "val2") + try { + abcLogger.info("xyz") + } finally { + MDC.clear() + } + + then: + + 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.INFO) + assertThat(log.getSeverityText()).isEqualTo("INFO") + assertThat(log.getAttributes().size()).isEqualTo(2) + assertThat(log.getAttributes().get(AttributeKey.stringKey("logback.mdc.key1"))).isEqualTo("val1") + assertThat(log.getAttributes().get(AttributeKey.stringKey("logback.mdc.key2"))).isEqualTo("val2") + } } diff --git a/instrumentation/logback/logback-appender-1.0/library/build.gradle.kts b/instrumentation/logback/logback-appender-1.0/library/build.gradle.kts new file mode 100644 index 000000000000..6a7876713331 --- /dev/null +++ b/instrumentation/logback/logback-appender-1.0/library/build.gradle.kts @@ -0,0 +1,20 @@ +plugins { + id("otel.library-instrumentation") +} + +dependencies { + api(project(":instrumentation-api-appender")) + + library("ch.qos.logback:logback-classic:0.9.16") + + testImplementation(project(":instrumentation-sdk-appender")) + testImplementation("io.opentelemetry:opentelemetry-sdk-logs") + testImplementation("io.opentelemetry:opentelemetry-sdk-testing") + + testImplementation("org.mockito:mockito-core") +} + +tasks.withType().configureEach { + // TODO run tests both with and without experimental log attributes + jvmArgs("-Dotel.instrumentation.logback-appender.experimental.capture-mdc-attributes=*") +} diff --git a/instrumentation/logback/logback-appender-1.0/library/src/main/java/io/opentelemetry/instrumentation/logback/appender/v1_0/internal/LoggingEventMapper.java b/instrumentation/logback/logback-appender-1.0/library/src/main/java/io/opentelemetry/instrumentation/logback/appender/v1_0/internal/LoggingEventMapper.java new file mode 100644 index 000000000000..619fbe2e8f7c --- /dev/null +++ b/instrumentation/logback/logback-appender-1.0/library/src/main/java/io/opentelemetry/instrumentation/logback/appender/v1_0/internal/LoggingEventMapper.java @@ -0,0 +1,163 @@ +/* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ + +package io.opentelemetry.instrumentation.logback.appender.v1_0.internal; + +import static java.util.Collections.emptyList; + +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.classic.spi.ThrowableProxy; +import io.opentelemetry.api.common.AttributeKey; +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.instrumentation.api.cache.Cache; +import io.opentelemetry.instrumentation.api.config.Config; +import io.opentelemetry.semconv.trace.attributes.SemanticAttributes; +import java.io.PrintWriter; +import java.io.StringWriter; +import java.util.List; +import java.util.Map; +import java.util.concurrent.TimeUnit; + +public final class LoggingEventMapper { + + public static final LoggingEventMapper INSTANCE = new LoggingEventMapper(); + + private static final Cache> mdcAttributeKeys = Cache.bounded(100); + + private final List captureMdcAttributes; + + // cached as an optimization + private final boolean captureAllMdcAttributes; + + private LoggingEventMapper() { + this( + Config.get() + .getList( + "otel.instrumentation.logback-appender.experimental.capture-mdc-attributes", + emptyList())); + } + + // visible for testing + LoggingEventMapper(List captureMdcAttributes) { + this.captureMdcAttributes = captureMdcAttributes; + this.captureAllMdcAttributes = + captureMdcAttributes.size() == 1 && captureMdcAttributes.get(0).equals("*"); + } + + public void capture(final ILoggingEvent event) { + LogBuilder builder = + GlobalLogEmitterProvider.get() + .logEmitterBuilder(event.getLoggerName()) + .build() + .logBuilder(); + mapLoggingEvent(builder, event); + builder.emit(); + } + + /** + * Map the {@link ILoggingEvent} data model onto the {@link LogBuilder}. Unmapped fields include: + * + *
    + *
  • Thread name - {@link ILoggingEvent#getThreadName()} + *
  • Marker - {@link ILoggingEvent#getMarker()} + *
  • Mapped diagnostic context - {@link ILoggingEvent#getMDCPropertyMap()} + *
+ */ + private void mapLoggingEvent(LogBuilder builder, ILoggingEvent loggingEvent) { + // message + String message = loggingEvent.getMessage(); + if (message != null) { + builder.setBody(message); + } + + // time + long timestamp = loggingEvent.getTimeStamp(); + builder.setEpoch(timestamp, TimeUnit.MILLISECONDS); + + // level + Level level = loggingEvent.getLevel(); + if (level != null) { + builder.setSeverity(levelToSeverity(level)); + builder.setSeverityText(level.levelStr); + } + + AttributesBuilder attributes = Attributes.builder(); + + // throwable + Object throwableProxy = loggingEvent.getThrowableProxy(); + Throwable throwable = null; + if (throwableProxy instanceof ThrowableProxy) { + // there is only one other subclass of ch.qos.logback.classic.spi.IThrowableProxy + // and it is only used for logging exceptions over the wire + throwable = ((ThrowableProxy) throwableProxy).getThrowable(); + } + if (throwable != null) { + setThrowable(attributes, throwable); + } + + captureMdcAttributes(attributes, loggingEvent.getMDCPropertyMap()); + + builder.setAttributes(attributes.build()); + + // span context + builder.setContext(Context.current()); + } + + // visible for testing + void captureMdcAttributes(AttributesBuilder attributes, Map mdcProperties) { + + if (captureAllMdcAttributes) { + for (Map.Entry entry : mdcProperties.entrySet()) { + attributes.put(getMdcAttributeKey(entry.getKey()), entry.getValue()); + } + return; + } + + for (String key : captureMdcAttributes) { + String value = mdcProperties.get(key); + if (value != null) { + attributes.put(getMdcAttributeKey(key), value); + } + } + } + + public static AttributeKey getMdcAttributeKey(String key) { + return mdcAttributeKeys.computeIfAbsent(key, k -> AttributeKey.stringKey("logback.mdc." + k)); + } + + private static void setThrowable(AttributesBuilder attributes, Throwable throwable) { + // 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()); + } + + private static Severity levelToSeverity(Level level) { + switch (level.levelInt) { + case Level.ALL_INT: + case Level.TRACE_INT: + return Severity.TRACE; + case Level.DEBUG_INT: + return Severity.DEBUG; + case Level.INFO_INT: + return Severity.INFO; + case Level.WARN_INT: + return Severity.WARN; + case Level.ERROR_INT: + return Severity.ERROR; + case Level.OFF_INT: + default: + return Severity.UNDEFINED_SEVERITY_NUMBER; + } + } +} diff --git a/instrumentation/logback/logback-appender-1.0/library/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/internal/LoggingEventMapperTest.java b/instrumentation/logback/logback-appender-1.0/library/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/internal/LoggingEventMapperTest.java new file mode 100644 index 000000000000..8fd44d541e0e --- /dev/null +++ b/instrumentation/logback/logback-appender-1.0/library/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/internal/LoggingEventMapperTest.java @@ -0,0 +1,73 @@ +/* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ + +package io.opentelemetry.instrumentation.logback.appender.v1_0.internal; + +import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.assertThat; +import static java.util.Collections.emptyList; +import static java.util.Collections.singletonList; +import static org.assertj.core.api.Assertions.entry; + +import io.opentelemetry.api.common.AttributeKey; +import io.opentelemetry.api.common.Attributes; +import io.opentelemetry.api.common.AttributesBuilder; +import java.util.HashMap; +import java.util.Map; +import org.junit.Test; + +public class LoggingEventMapperTest { + + @Test + public void testDefault() { + // given + LoggingEventMapper mapper = new LoggingEventMapper(emptyList()); + Map contextData = new HashMap<>(); + contextData.put("key1", "value1"); + contextData.put("key2", "value2"); + AttributesBuilder attributes = Attributes.builder(); + + // when + mapper.captureMdcAttributes(attributes, contextData); + + // then + assertThat(attributes.build()).isEmpty(); + } + + @Test + public void testSome() { + // given + LoggingEventMapper mapper = new LoggingEventMapper(singletonList("key2")); + Map contextData = new HashMap<>(); + contextData.put("key1", "value1"); + contextData.put("key2", "value2"); + AttributesBuilder attributes = Attributes.builder(); + + // when + mapper.captureMdcAttributes(attributes, contextData); + + // then + assertThat(attributes.build()) + .containsOnly(entry(AttributeKey.stringKey("logback.mdc.key2"), "value2")); + } + + @Test + public void testAll() { + // given + LoggingEventMapper mapper = new LoggingEventMapper(singletonList("*")); + Map contextData = new HashMap<>(); + contextData.put("key1", "value1"); + contextData.put("key2", "value2"); + AttributesBuilder attributes = Attributes.builder(); + + // when + mapper.captureMdcAttributes(attributes, contextData); + + // then + assertThat(attributes.build()) + .containsOnly( + entry(AttributeKey.stringKey("logback.mdc.key1"), "value1"), + entry(AttributeKey.stringKey("logback.mdc.key2"), "value2")); + } +} diff --git a/settings.gradle.kts b/settings.gradle.kts index ec0c9912b324..7f1692ad8a45 100644 --- a/settings.gradle.kts +++ b/settings.gradle.kts @@ -276,6 +276,7 @@ include(":instrumentation:log4j:log4j-context-data:log4j-context-data-2-common:t include(":instrumentation:log4j:log4j-appender-2.16:javaagent") include(":instrumentation:log4j:log4j-appender-2.16:library") include(":instrumentation:logback:logback-appender-1.0:javaagent") +include(":instrumentation:logback:logback-appender-1.0:library") include(":instrumentation:logback:logback-mdc-1.0:javaagent") include(":instrumentation:logback:logback-mdc-1.0:library") include(":instrumentation:logback:logback-mdc-1.0:testing")