Application logger bridge: Spring Boot support (#8228)

conventions/src/main/kotlin/io.opentelemetry.instrumentation.javaagent-testing.gradle.kts

@@ -79,6 +79,8 @@ class JavaagentTestArgumentsProvider(
   override fun asArguments(): Iterable<String> = listOf(
     "-Dotel.javaagent.debug=true",
     "-javaagent:${agentShadowJar.absolutePath}",
+    // make the path to the javaagent available to tests
+    "-Dotel.javaagent.testing.javaagent-jar-path=${agentShadowJar.absolutePath}",
     "-Dotel.javaagent.experimental.initializer.jar=${shadowJar.absolutePath}",
     "-Dotel.javaagent.testing.additional-library-ignores.enabled=false",
     "-Dotel.javaagent.testing.fail-on-context-leak=${findProperty("failOnContextLeak") != false}",

instrumentation/internal/internal-application-logger/bootstrap/src/main/java/io/opentelemetry/javaagent/bootstrap/logging/ApplicationLoggerFlags.java

@@ -0,0 +1,47 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+package io.opentelemetry.javaagent.bootstrap.logging;
+
+import java.util.concurrent.atomic.AtomicBoolean;
+
+public final class ApplicationLoggerFlags {
+
+  // by default, the instrumentation aims to instrument the slf4j LoggerFactory; unless the presence
+  // of the SpringApplication class is detected, in which case we disable the LoggerFactory
+  // instrumentation and instead enable the Spring Boot's LoggingApplicationListener instrumentation
+  private static final AtomicBoolean bridgeLoggerFactory = new AtomicBoolean(true);
+  private static final AtomicBoolean bridgeSpringBootLogging = new AtomicBoolean(false);
+
+  private ApplicationLoggerFlags() {}
+
+  /**
+   * Disables the sfl4j {@code LoggerFactory} instrumentation; and instead enables the Spring Boot
+   * {@code LoggingApplicationListener} instrumentation. In Spring Boot, an implementation of {@code
+   * LoggingApplicationListener} is responsible for initializing the logging library. Even though
+   * slf4j (and its {@code LoggerFactory}) is actually logged earlier, it is not usable until the
+   * {@code LoggingApplicationListener} finishes its initialization process.
+   */
+  public static void setSpringBootApp() {
+    bridgeLoggerFactory.set(false);
+    bridgeSpringBootLogging.set(true);
+  }
+
+  /**
+   * Return true when the {@code LoggerFactory} instrumentation is allowed to install an application
+   * logger bridge. Will return true at most once.
+   */
+  public static boolean bridgeLoggerFactory() {
+    return bridgeLoggerFactory.compareAndSet(true, false);
+  }
+
+  /**
+   * Return true when the {@code LoggingApplicationListener} instrumentation is allowed to install
+   * an application logger bridge. Will return true at most once.
+   */
+  public static boolean bridgeSpringBootLogging() {
+    return bridgeSpringBootLogging.compareAndSet(true, false);
+  }
+}

instrumentation/internal/internal-application-logger/javaagent/build.gradle.kts

@@ -9,6 +9,13 @@ muzzle {
     versions.set("[1.4.0,)")
     assertInverse.set(true)
   }
+  pass {
+    group.set("org.springframework.boot")
+    module.set("spring-boot")
+    // pre-1.2.0 versions don't have the Slf4JLoggingSystem
+    versions.set("[1.2.0,)")
+    extraDependency("org.springframework.boot:spring-boot-starter-logging")
+  }
 }
 
 dependencies {
@@ -22,4 +29,21 @@ dependencies {
       strictly("1.4.0")
     }
   }
+
+  if (findProperty("testLatestDeps") as Boolean) {
+    testImplementation("ch.qos.logback:logback-classic:+")
+  } else {
+    testImplementation("ch.qos.logback:logback-classic") {
+      version {
+        strictly("1.2.11")
+      }
+    }
+    testImplementation("org.slf4j:slf4j-api") {
+      version {
+        strictly("1.7.36")
+      }
+    }
+  }
+
+  testLibrary("org.springframework.boot:spring-boot-starter:2.5.3")
 }

instrumentation/internal/internal-application-logger/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/internal/logging/ApplicationLoggingIgnoredTypesConfigurer.java

@@ -16,5 +16,8 @@ public final class ApplicationLoggingIgnoredTypesConfigurer implements IgnoredTy
   @Override
   public void configure(IgnoredTypesBuilder builder, ConfigProperties config) {
     builder.allowClass("org.slf4j.LoggerFactory");
+    builder.allowClass("org.springframework.boot.SpringApplication");
+    builder.allowClass("org.springframework.boot.logging.LoggingApplicationListener");
+    builder.allowClass("org.springframework.boot.context.logging.LoggingApplicationListener");
   }
 }

instrumentation/internal/internal-application-logger/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/internal/logging/ApplicationLoggingInstrumentationModule.java

@@ -5,7 +5,7 @@
 
 package io.opentelemetry.javaagent.instrumentation.internal.logging;
 
-import static java.util.Collections.singletonList;
+import static java.util.Arrays.asList;
 
 import com.google.auto.service.AutoService;
 import io.opentelemetry.javaagent.extension.instrumentation.InstrumentationModule;
@@ -28,6 +28,9 @@ public boolean defaultEnabled(ConfigProperties config) {
 
   @Override
   public List<TypeInstrumentation> typeInstrumentations() {
-    return singletonList(new LoggerFactoryInstrumentation());
+    return asList(
+        new LoggerFactoryInstrumentation(),
+        new SpringApplicationInstrumentation(),
+        new LoggingApplicationListenerInstrumentation());
   }
 }

instrumentation/internal/internal-application-logger/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/internal/logging/LoggerFactoryInstrumentation.java

@@ -8,6 +8,7 @@
 import static net.bytebuddy.matcher.ElementMatchers.named;
 import static net.bytebuddy.matcher.ElementMatchers.takesArguments;
 
+import io.opentelemetry.javaagent.bootstrap.logging.ApplicationLoggerFlags;
 import io.opentelemetry.javaagent.extension.instrumentation.TypeInstrumentation;
 import io.opentelemetry.javaagent.extension.instrumentation.TypeTransformer;
 import net.bytebuddy.asm.Advice;
@@ -34,7 +35,9 @@ public static class GetLoggerFactoryAdvice {
 
     @Advice.OnMethodExit(suppress = Throwable.class)
     public static void onExit() {
-      Slf4jApplicationLoggerBridge.install();
+      if (ApplicationLoggerFlags.bridgeLoggerFactory()) {
+        Slf4jApplicationLoggerBridge.install();
+      }
     }
   }
 }

instrumentation/internal/internal-application-logger/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/internal/logging/LoggingApplicationListenerInstrumentation.java

@@ -0,0 +1,46 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+package io.opentelemetry.javaagent.instrumentation.internal.logging;
+
+import static net.bytebuddy.matcher.ElementMatchers.named;
+import static net.bytebuddy.matcher.ElementMatchers.namedOneOf;
+
+import io.opentelemetry.javaagent.bootstrap.logging.ApplicationLoggerFlags;
+import io.opentelemetry.javaagent.extension.instrumentation.TypeInstrumentation;
+import io.opentelemetry.javaagent.extension.instrumentation.TypeTransformer;
+import net.bytebuddy.asm.Advice;
+import net.bytebuddy.description.type.TypeDescription;
+import net.bytebuddy.matcher.ElementMatcher;
+
+public class LoggingApplicationListenerInstrumentation implements TypeInstrumentation {
+
+  @Override
+  public ElementMatcher<TypeDescription> typeMatcher() {
+    return namedOneOf(
+        // spring boot 1.x
+        "org.springframework.boot.logging.LoggingApplicationListener",
+        // spring boot 2.+
+        "org.springframework.boot.context.logging.LoggingApplicationListener");
+  }
+
+  @Override
+  public void transform(TypeTransformer transformer) {
+    // the logger is properly initialized once this method exits
+    transformer.applyAdviceToMethod(
+        named("initialize"), this.getClass().getName() + "$InitializeAdvice");
+  }
+
+  @SuppressWarnings("unused")
+  public static class InitializeAdvice {
+
+    @Advice.OnMethodExit(suppress = Throwable.class)
+    public static void onExit() {
+      if (ApplicationLoggerFlags.bridgeSpringBootLogging()) {
+        Slf4jApplicationLoggerBridge.install();
+      }
+    }
+  }
+}

instrumentation/internal/internal-application-logger/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/internal/logging/Slf4jApplicationLoggerBridge.java

@@ -7,19 +7,14 @@
 
 import io.opentelemetry.javaagent.bootstrap.InternalLogger;
 import io.opentelemetry.javaagent.bootstrap.logging.ApplicationLoggerBridge;
-import java.util.concurrent.atomic.AtomicBoolean;
 import javax.annotation.Nullable;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
 public final class Slf4jApplicationLoggerBridge implements InternalLogger.Factory {
 
-  private static final AtomicBoolean installed = new AtomicBoolean();
-
   public static void install() {
-    if (installed.compareAndSet(false, true)) {
-      ApplicationLoggerBridge.installApplicationLogger(new Slf4jApplicationLoggerBridge());
-    }
+    ApplicationLoggerBridge.installApplicationLogger(new Slf4jApplicationLoggerBridge());
   }
 
   @Override

instrumentation/internal/internal-application-logger/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/internal/logging/SpringApplicationInstrumentation.java

@@ -0,0 +1,40 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+package io.opentelemetry.javaagent.instrumentation.internal.logging;
+
+import static net.bytebuddy.matcher.ElementMatchers.isTypeInitializer;
+import static net.bytebuddy.matcher.ElementMatchers.named;
+
+import io.opentelemetry.javaagent.bootstrap.logging.ApplicationLoggerFlags;
+import io.opentelemetry.javaagent.extension.instrumentation.TypeInstrumentation;
+import io.opentelemetry.javaagent.extension.instrumentation.TypeTransformer;
+import net.bytebuddy.asm.Advice;
+import net.bytebuddy.description.type.TypeDescription;
+import net.bytebuddy.matcher.ElementMatcher;
+
+public class SpringApplicationInstrumentation implements TypeInstrumentation {
+
+  @Override
+  public ElementMatcher<TypeDescription> typeMatcher() {
+    return named("org.springframework.boot.SpringApplication");
+  }
+
+  @Override
+  public void transform(TypeTransformer transformer) {
+    transformer.applyAdviceToMethod(
+        isTypeInitializer(), this.getClass().getName() + "$TypeInitAdvice");
+  }
+
+  @SuppressWarnings("unused")
+  public static class TypeInitAdvice {
+
+    @Advice.OnMethodEnter(suppress = Throwable.class)
+    public static void onEnter() {
+      // mark the instrumented application as spring boot app
+      ApplicationLoggerFlags.setSpringBootApp();
+    }
+  }
+}

instrumentation/internal/internal-application-logger/javaagent/src/test/java/io/opentelemetry/javaagent/instrumentation/internal/logging/ApplicationLoggerInstrumentationTest.java

@@ -0,0 +1,78 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+package io.opentelemetry.javaagent.instrumentation.internal.logging;
+
+import static java.util.Arrays.asList;
+import static org.assertj.core.api.Assertions.assertThat;
+
+import java.io.BufferedReader;
+import java.io.File;
+import java.io.IOException;
+import java.io.InputStream;
+import java.io.InputStreamReader;
+import java.nio.charset.StandardCharsets;
+import java.util.ArrayList;
+import java.util.List;
+import java.util.concurrent.CompletableFuture;
+import java.util.concurrent.TimeUnit;
+import org.junit.jupiter.params.ParameterizedTest;
+import org.junit.jupiter.params.provider.ValueSource;
+
+class ApplicationLoggerInstrumentationTest {
+
+  @ParameterizedTest
+  @ValueSource(classes = {TestApp.class, TestSpringApp.class})
+  void shouldUseApplicationLogger(Class<?> mainClass) throws Exception {
+    // gradle itself includes slf4j, and initializes it way before this method is executed
+    // to remove the gradle interference, we're running the test apps in separate subprocesses
+    List<String> logs = forkAndRun(mainClass.getName());
+
+    assertThat(logs)
+        .anyMatch(
+            log ->
+                log.startsWith(
+                    "INFO io.opentelemetry.javaagent.tooling.VersionLogger :: opentelemetry-javaagent - version: "));
+  }
+
+  private static List<String> forkAndRun(String mainClassName) throws Exception {
+    String javaPath =
+        System.getProperty("java.home") + File.separator + "bin" + File.separator + "java";
+    String javaagentPath = System.getProperty("otel.javaagent.testing.javaagent-jar-path");
+
+    Process process =
+        new ProcessBuilder(
+                asList(
+                    javaPath,
+                    "-javaagent:" + javaagentPath,
+                    "-cp",
+                    System.getProperty("java.class.path"),
+                    "-Dotel.sdk.disabled=true",
+                    "-Dotel.javaagent.logging=application",
+                    mainClassName))
+            .redirectErrorStream(true)
+            .start();
+    InputStream stdout = process.getInputStream();
+
+    CompletableFuture<List<String>> output =
+        CompletableFuture.supplyAsync(
+            () -> {
+              try (BufferedReader reader =
+                  new BufferedReader(new InputStreamReader(stdout, StandardCharsets.UTF_8))) {
+                List<String> lines = new ArrayList<>();
+                String line;
+                while ((line = reader.readLine()) != null) {
+                  lines.add(line);
+                }
+                return lines;
+              } catch (IOException e) {
+                throw new AssertionError("Unexpected error while retrieving subprocess output", e);
+              }
+            });
+
+    process.waitFor(10, TimeUnit.SECONDS);
+    return output.join();
+  }
+}

instrumentation/internal/internal-application-logger/javaagent/src/test/java/io/opentelemetry/javaagent/instrumentation/internal/logging/TestApp.java

@@ -0,0 +1,19 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+package io.opentelemetry.javaagent.instrumentation.internal.logging;
+
+import java.util.concurrent.TimeUnit;
+import org.slf4j.LoggerFactory;
+
+@SuppressWarnings("OtelPrivateConstructorForUtilityClass")
+public class TestApp {
+
+  public static void main(String[] args) throws Exception {
+    // pretend to do some work for a second
+    TimeUnit.SECONDS.sleep(1);
+    LoggerFactory.getLogger(TestApp.class).info("Done!");
+  }
+}

instrumentation/internal/internal-application-logger/javaagent/src/test/java/io/opentelemetry/javaagent/instrumentation/internal/logging/TestSpringApp.java

@@ -0,0 +1,26 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+package io.opentelemetry.javaagent.instrumentation.internal.logging;
+
+import java.util.concurrent.TimeUnit;
+import org.slf4j.LoggerFactory;
+import org.springframework.boot.SpringApplication;
+import org.springframework.boot.autoconfigure.SpringBootApplication;
+import org.springframework.context.ConfigurableApplicationContext;
+
+@SpringBootApplication
+@SuppressWarnings("OtelPrivateConstructorForUtilityClass")
+public class TestSpringApp {
+
+  public static void main(String[] args) throws Exception {
+    SpringApplication app = new SpringApplication(TestSpringApp.class);
+    try (ConfigurableApplicationContext ignored = app.run()) {
+      // pretend to do some work for a second
+      TimeUnit.SECONDS.sleep(1);
+      LoggerFactory.getLogger(TestSpringApp.class).info("Done!");
+    }
+  }
+}

instrumentation/internal/internal-application-logger/javaagent/src/test/resources/logback.xml

@@ -0,0 +1,20 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<configuration>
+
+  <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
+    <layout class="ch.qos.logback.classic.PatternLayout">
+      <Pattern>
+        %level %logger :: %msg%n
+      </Pattern>
+    </layout>
+  </appender>
+
+  <root level="INFO">
+    <appender-ref ref="console"/>
+  </root>
+
+  <logger name="io.opentelemetry" level="DEBUG">
+    <appender-ref ref="console"/>
+  </logger>
+
+</configuration>