open-telemetry · trask · Dec 20, 2021 · Dec 17, 2021 · Dec 19, 2021 · Dec 20, 2021
@@ -0,0 +1,23 @@
+plugins {
+  id("otel.javaagent-instrumentation")
+}
+
+muzzle {
+  pass {
+    group.set("ch.qos.logback")
+    module.set("logback-classic")
+    versions.set("[0.9.16,)")
+    skip("0.9.6") // has dependency on SNAPSHOT org.slf4j:slf4j-api:1.4.0-SNAPSHOT
+    skip("0.8") // has dependency on non-existent org.slf4j:slf4j-api:1.1.0-RC0
+    skip("0.6") // has dependency on pom only javax.jms:jms:1.1
+    assertInverse.set(true)
+  }
+}
+
+dependencies {
+  library("ch.qos.logback:logback-classic:0.9.16")
+
+  compileOnly(project(":instrumentation-api-appender"))
+
+  testImplementation("org.awaitility:awaitility")
+}
@@ -0,0 +1,106 @@
+/*
+ * 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:
+   *
+   * <ul>
+   *   <li>Thread name - {@link ILoggingEvent#getThreadName()}
+   *   <li>Marker - {@link ILoggingEvent#getMarker()}
+   *   <li>Mapped diagnostic context - {@link ILoggingEvent#getMDCPropertyMap()}
+   * </ul>
+   */
+  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() {}
+}
@@ -0,0 +1,61 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+package io.opentelemetry.javaagent.instrumentation.logback.appender.v1_0;
+
+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 ch.qos.logback.classic.spi.ILoggingEvent;
+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 net.bytebuddy.asm.Advice;
+import net.bytebuddy.description.type.TypeDescription;
+import net.bytebuddy.matcher.ElementMatcher;
+
+class LogbackInstrumentation implements TypeInstrumentation {
+
+  @Override
+  public ElementMatcher<TypeDescription> typeMatcher() {
+    return named("ch.qos.logback.classic.Logger");
+  }
+
+  @Override
+  public void transform(TypeTransformer transformer) {
+    transformer.applyAdviceToMethod(
+        isMethod()
+            .and(isPublic())
+            .and(named("callAppenders"))
+            .and(takesArguments(1))
+            .and(takesArgument(0, named("ch.qos.logback.classic.spi.ILoggingEvent"))),
+        LogbackInstrumentation.class.getName() + "$CallAppendersAdvice");
+  }
+
+  @SuppressWarnings("unused")
+  public static class CallAppendersAdvice {
+
+    @Advice.OnMethodEnter(suppress = Throwable.class)
+    public static void methodEnter(
+        @Advice.Argument(0) final ILoggingEvent event,
+        @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) {
+        LogbackHelper.capture(event);
+      }
+    }
+
+    @Advice.OnMethodExit(onThrowable = Throwable.class, suppress = Throwable.class)
+    public static void methodExit(@Advice.Local("otelCallDepth") CallDepth callDepth) {
+      callDepth.decrementAndGet();
+    }
+  }
+}
@@ -0,0 +1,26 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+package io.opentelemetry.javaagent.instrumentation.logback.appender.v1_0;
+
+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 LogbackInstrumentationModule extends InstrumentationModule {
+
+  public LogbackInstrumentationModule() {
+    super("logback-appender", "logback-appender-1.0");
+  }
+
+  @Override
+  public List<TypeInstrumentation> typeInstrumentations() {
+    return singletonList(new LogbackInstrumentation());
+  }
+}
@@ -0,0 +1,96 @@
+/*
+ * 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 org.slf4j.Logger
+import org.slf4j.LoggerFactory
+
+import static io.opentelemetry.instrumentation.test.utils.TraceUtils.runUnderTrace
+import static org.assertj.core.api.Assertions.assertThat
+import static org.awaitility.Awaitility.await
+
+class LogbackTest extends AgentInstrumentationSpecification {
+
+  private static final Logger abcLogger = LoggerFactory.getLogger("abc");
+  private static final Logger defLogger = LoggerFactory.getLogger("def");
+
+  def "test logger=#loggerName method=#testMethod with exception=#exception and parent=#parent"() {
+    when:
+    if (parent) {
+      runUnderTrace("parent") {
+        if (exception) {
+          logger."$testMethod"("xyz", new IllegalStateException("hello"))
+        } else {
+          logger."$testMethod"("xyz")
+        }
+      }
+    } else {
+      if (exception) {
+        logger."$testMethod"("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(loggerName)
+      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(LogbackTest.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 span is captured
+      logs.size() == 0
+    }
+
+    where:
+    [args, exception, parent] << [
+      [
+        [abcLogger, "abc", "debug", null, null],
+        [abcLogger, "abc", "info", Severity.INFO, "INFO"],
+        [abcLogger, "abc", "warn", Severity.WARN, "WARN"],
+        [abcLogger, "abc", "error", Severity.ERROR, "ERROR"],
+        [defLogger, "def", "debug", null, null],
+        [defLogger, "def", "info", null, null],
+        [defLogger, "def", "warn", Severity.WARN, "WARN"],
+        [defLogger, "def", "error", Severity.ERROR, "ERROR"]
+      ],
+      [true, false],
+      [true, false]
+    ].combinations()
+
+    logger = args[0]
+    loggerName = args[1]
+    testMethod = args[2]
+    severity = args[3]
+    severityText = args[4]
-    logger = args[0]
-    loggerName = args[1]
-    testMethod = args[2]
-    severity = args[3]
-    severityText = args[4]
+    [logger, loggerName, testMethod, severity, severityText] = args
-    logger = args[0]
-    loggerName = args[1]
-    testMethod = args[2]
-    severity = args[3]
-    severityText = args[4]
+    [logger, loggerName, testMethod, severity, severityText] = args
+  }
+}
@@ -0,0 +1,21 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<configuration>
+
+  <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
+    <encoder>
+      <pattern>
+        %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n
+      </pattern>
+    </encoder>
+  </appender>
+
+  <logger name="abc" level="INFO"/>
+  <logger name="def" level="WARN"/>
+
+  <root level="INFO">
+    <appender-ref ref="console"/>
+  </root>
+
+  <logger name="org.testcontainers" level="WARN"/>
+  <logger name="io.opentelemetry.testing.internal" level="WARN"/>
+</configuration>
@@ -11,11 +11,11 @@ muzzle {
 }
 
 dependencies {
-  implementation(project(":instrumentation:logback-1.0:library"))
+  implementation(project(":instrumentation:logback:logback-mdc-1.0:library"))
 
   library("ch.qos.logback:logback-classic:1.0.0")
 
-  testImplementation(project(":instrumentation:logback-1.0:testing"))
+  testImplementation(project(":instrumentation:logback:logback-mdc-1.0:testing"))
 
   // 1.3+ contains breaking changes, check back after it stabilizes.
   latestDepTestLibrary("ch.qos.logback:logback-classic:1.2.+")

@@ -3,7 +3,7 @@
  * SPDX-License-Identifier: Apache-2.0
  */
 
-package io.opentelemetry.javaagent.instrumentation.logback.v1_0;
+package io.opentelemetry.javaagent.instrumentation.logback.mdc.v1_0;
 
 import static java.util.Arrays.asList;
 
@@ -13,9 +13,9 @@
 import java.util.List;
 
 @AutoService(InstrumentationModule.class)
-public class LogbackInstrumentationModule extends InstrumentationModule {
-  public LogbackInstrumentationModule() {
-    super("logback", "logback-1.0");
+public class LogbackMdcInstrumentationModule extends InstrumentationModule {
+  public LogbackMdcInstrumentationModule() {
+    super("logback-mdc", "logback-mdc-1.0");
   }
 
   @Override

@@ -3,7 +3,7 @@
  * SPDX-License-Identifier: Apache-2.0
  */
 
-package io.opentelemetry.javaagent.instrumentation.logback.v1_0;
+package io.opentelemetry.javaagent.instrumentation.logback.mdc.v1_0;
 
 import static net.bytebuddy.matcher.ElementMatchers.isMethod;
 import static net.bytebuddy.matcher.ElementMatchers.isPublic;

@@ -3,7 +3,7 @@
  * SPDX-License-Identifier: Apache-2.0
  */
 
-package io.opentelemetry.javaagent.instrumentation.logback.v1_0;
+package io.opentelemetry.javaagent.instrumentation.logback.mdc.v1_0;
 
 import static io.opentelemetry.instrumentation.api.log.LoggingContextConstants.SPAN_ID;
 import static io.opentelemetry.instrumentation.api.log.LoggingContextConstants.TRACE_FLAGS;