implement spans debug logging (#704)

Author: SylvainJuge

custom/src/main/java/co/elastic/otel/ElasticAutoConfigurationCustomizerProvider.java

@@ -22,6 +22,7 @@
 import co.elastic.otel.dynamicconfig.BlockableMetricExporter;
 import co.elastic.otel.dynamicconfig.BlockableSpanExporter;
 import co.elastic.otel.dynamicconfig.CentralConfig;
+import co.elastic.otel.logging.AgentLog;
 import com.google.auto.service.AutoService;
 import io.opentelemetry.api.common.AttributeKey;
 import io.opentelemetry.sdk.autoconfigure.spi.AutoConfigurationCustomizer;
@@ -72,6 +73,7 @@ public void customize(AutoConfigurationCustomizer autoConfiguration) {
     autoConfiguration.addTracerProviderCustomizer(
         (providerBuilder, properties) -> {
           CentralConfig.init(providerBuilder, properties);
+          AgentLog.addSpanLoggingIfRequired(providerBuilder, properties);
           return providerBuilder;
         });
   }

internal-logging/build.gradle.kts

@@ -10,6 +10,9 @@ dependencies {
 
   compileOnly("io.opentelemetry.javaagent:opentelemetry-javaagent-tooling")
   compileOnly("io.opentelemetry.javaagent:opentelemetry-javaagent-bootstrap")
+  compileOnly("io.opentelemetry:opentelemetry-sdk-extension-autoconfigure-spi")
+  compileOnly("io.opentelemetry:opentelemetry-exporter-logging")
+  compileOnly("io.opentelemetry:opentelemetry-exporter-logging-otlp")
   compileOnly(libs.slf4j.api)
   implementation(libs.bundles.log4j2) {
     // Workaround for https://github.com/apache/logging-log4j2/issues/3754

internal-logging/src/main/java/co/elastic/otel/logging/AgentLog.java

@@ -18,6 +18,19 @@
  */
 package co.elastic.otel.logging;
 
+import static java.util.Collections.emptyList;
+
+import io.opentelemetry.exporter.logging.LoggingSpanExporter;
+import io.opentelemetry.exporter.logging.otlp.OtlpJsonLoggingSpanExporter;
+import io.opentelemetry.sdk.autoconfigure.spi.ConfigProperties;
+import io.opentelemetry.sdk.common.CompletableResultCode;
+import io.opentelemetry.sdk.trace.SdkTracerProviderBuilder;
+import io.opentelemetry.sdk.trace.data.SpanData;
+import io.opentelemetry.sdk.trace.export.SimpleSpanProcessor;
+import io.opentelemetry.sdk.trace.export.SpanExporter;
+import java.util.Collection;
+import java.util.List;
+import java.util.concurrent.atomic.AtomicBoolean;
 import org.apache.logging.log4j.Level;
 import org.apache.logging.log4j.core.config.Configurator;
 import org.apache.logging.log4j.core.config.builder.api.ConfigurationBuilder;
@@ -26,14 +39,37 @@
 
 public class AgentLog {
 
+  /** Upstream instrumentation debug boolean option */
+  public static final String OTEL_JAVAAGENT_DEBUG = "otel.javaagent.debug";
+
   private static final String PATTERN = "%d{DEFAULT} [%t] %-5level %logger{36} - %msg{nolookups}%n";
 
-  // logger is an empty string
+  /** root logger is an empty string */
   private static final String ROOT_LOGGER_NAME = "";
 
+  private static boolean logPlainText = false;
+
+  /**
+   * debug span logging exporter that can be controlled at runtime, only used when logging span
+   * exporter has not been explicitly configured.
+   */
+  private static DebugLogSpanExporter debugLogSpanExporter = null;
+
   private AgentLog() {}
 
-  public static void init() {
+  /**
+   * Initializes agent logging
+   *
+   * @param usePlainTextLog {@literal true} to use plain text logging, `{@literal false} to use JSON
+   * @param initialLevel initial log level to configure
+   */
+  public static void init(boolean usePlainTextLog, Level initialLevel) {
+    internalInit();
+    setLevel(initialLevel);
+    logPlainText = usePlainTextLog;
+  }
+
+  private static void internalInit() {
 
     ConfigurationBuilder<BuiltConfiguration> conf =
         ConfigurationBuilderFactory.newConfigurationBuilder();
@@ -47,6 +83,25 @@ public static void init() {
     Configurator.initialize(conf.build(false));
   }
 
+  public static void addSpanLoggingIfRequired(
+      SdkTracerProviderBuilder providerBuilder, ConfigProperties config) {
+
+    // Replicate behavior of the upstream agent: span logging exporter is automatically added when
+    // not already present when debugging. When logging exporter has been explicitly configured,
+    // spans logging will be done by the explicitly configured logging exporter instance.
+
+    logPlainText = config.getBoolean(OTEL_JAVAAGENT_DEBUG, false);
+
+    List<String> exporters = config.getList("otel.traces.exporter", emptyList());
+    if (!exporters.contains("logging") && !exporters.contains("otlp-logging")) {
+      debugLogSpanExporter =
+          new DebugLogSpanExporter(
+              logPlainText ? LoggingSpanExporter.create() : OtlpJsonLoggingSpanExporter.create());
+
+      providerBuilder.addSpanProcessor(SimpleSpanProcessor.create(debugLogSpanExporter));
+    }
+  }
+
   public static void setLevel(String level) {
     switch (level) {
       case "trace":
@@ -80,18 +135,55 @@ public static void setLevel(String level) {
    *
    * @param level log level
    */
-  public static void setLevel(Level level) {
+  public static synchronized void setLevel(Level level) {
     // Using log4j2 implementation allows to change the log level programmatically at runtime
     // which is not directly possible through the slf4j API and simple implementation used in
     // upstream distribution.
 
     Configurator.setAllLevels(ROOT_LOGGER_NAME, level);
 
-    // when debugging we should avoid very chatty http client debug messages
+    boolean isDebug = level.intLevel() >= Level.DEBUG.intLevel();
+
+    // When debugging, we should avoid very chatty http client debug messages
     // this behavior is replicated from the upstream distribution.
-    if (level.intLevel() >= Level.DEBUG.intLevel()) {
+    if (isDebug) {
       Configurator.setLevel("okhttp3.internal.http2", Level.INFO);
       Configurator.setLevel("okhttp3.internal.concurrent.TaskRunner", Level.INFO);
     }
+
+    // when debugging the upstream otel agent configures an extra debug exporter
+    if (debugLogSpanExporter != null) {
+      debugLogSpanExporter.setEnabled(isDebug);
+    }
+  }
+
+  private static class DebugLogSpanExporter implements SpanExporter {
+
+    private final SpanExporter delegate;
+    private final AtomicBoolean enabled;
+
+    DebugLogSpanExporter(SpanExporter delegate) {
+      this.delegate = delegate;
+      this.enabled = new AtomicBoolean(false);
+    }
+
+    void setEnabled(boolean value) {
+      enabled.set(value);
+    }
+
+    @Override
+    public CompletableResultCode export(Collection<SpanData> spans) {
+      return enabled.get() ? delegate.export(spans) : CompletableResultCode.ofSuccess();
+    }
+
+    @Override
+    public CompletableResultCode flush() {
+      return enabled.get() ? delegate.flush() : CompletableResultCode.ofSuccess();
+    }
+
+    @Override
+    public CompletableResultCode shutdown() {
+      return enabled.get() ? delegate.shutdown() : CompletableResultCode.ofSuccess();
+    }
   }
 }

internal-logging/src/main/java/co/elastic/otel/logging/ElasticLoggingCustomizer.java

@@ -22,6 +22,7 @@
 import io.opentelemetry.javaagent.bootstrap.InternalLogger;
 import io.opentelemetry.javaagent.tooling.LoggingCustomizer;
 import io.opentelemetry.javaagent.tooling.config.EarlyInitAgentConfig;
+import java.util.Optional;
 import org.apache.logging.log4j.Level;
 import org.slf4j.LoggerFactory;
 
@@ -43,20 +44,19 @@ public void init(EarlyInitAgentConfig earlyConfig) {
     // make the agent internal logger delegate to slf4j, which will delegate to log4j
     InternalLogger.initialize(Slf4jInternalLogger::create);
 
-    AgentLog.init();
-
-    Level level = null;
-    if (earlyConfig.getBoolean("otel.javaagent.debug", false)) {
+    boolean upstreamDebugEnabled = earlyConfig.getBoolean(AgentLog.OTEL_JAVAAGENT_DEBUG, false);
+    Level level;
+    if (upstreamDebugEnabled) {
       // set debug logging when enabled through configuration to behave like the upstream
       // distribution
       level = Level.DEBUG;
     } else {
-      String levelConfig = earlyConfig.getString("elastic.otel.javaagent.log.level");
-      if (levelConfig != null) {
-        level = Level.getLevel(levelConfig);
-      }
+      level =
+          Optional.ofNullable(earlyConfig.getString("elastic.otel.javaagent.log.level"))
+              .map(Level::getLevel)
+              .orElse(Level.INFO);
     }
-    AgentLog.setLevel(level != null ? level : Level.INFO);
+    AgentLog.init(upstreamDebugEnabled, level);
   }
 
   @Override