Skip to content

Commit

Permalink
Add support for capturing logback mdc attributes (#4968)
Browse files Browse the repository at this point in the history
* Add support for capturing logback mdc attributes

* Spotless
  • Loading branch information
trask authored Jan 3, 2022
1 parent 4d7a5d5 commit 1a9b375
Show file tree
Hide file tree
Showing 8 changed files with 295 additions and 107 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -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<Test>().configureEach {
// TODO run tests both with and without experimental log attributes
jvmArgs("-Dotel.instrumentation.logback-appender.experimental.capture-mdc-attributes=*")
}

This file was deleted.

Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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);
}
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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")
}
}
Original file line number Diff line number Diff line change
@@ -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<Test>().configureEach {
// TODO run tests both with and without experimental log attributes
jvmArgs("-Dotel.instrumentation.logback-appender.experimental.capture-mdc-attributes=*")
}
Original file line number Diff line number Diff line change
@@ -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<String, AttributeKey<String>> mdcAttributeKeys = Cache.bounded(100);

private final List<String> 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<String> 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:
*
* <ul>
* <li>Thread name - {@link ILoggingEvent#getThreadName()}
* <li>Marker - {@link ILoggingEvent#getMarker()}
* <li>Mapped diagnostic context - {@link ILoggingEvent#getMDCPropertyMap()}
* </ul>
*/
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<String, String> mdcProperties) {

if (captureAllMdcAttributes) {
for (Map.Entry<String, String> 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<String> 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;
}
}
}
Loading

0 comments on commit 1a9b375

Please sign in to comment.