Propagate Log4j appender context through async loggers (#18937)

Author: trask

instrumentation/log4j/log4j-appender-2.17/library/README.md

@@ -103,4 +103,58 @@ The available settings are:
 
 The `otel.event.name` key is supported in `MapMessage` entries and context data entries. When present, its value is used as the log event name and is not emitted as an attribute.
 
+#### Async Loggers
+
+When using Log4j async loggers, for example `AsyncRoot`, `AsyncLogger`, or Log4j's built-in
+`AsyncAppender`, Log4j creates the `LogEvent` on the application thread and later invokes appenders
+on a background thread. To make the `OpenTelemetryAppender` emit logs with the application thread's
+full OpenTelemetry `Context`, configure Log4j to use the OpenTelemetry appender context data
+injector:
+
+```properties
+log4j2.ContextDataInjector=io.opentelemetry.instrumentation.log4j.appender.v2_17.OpenTelemetryAppenderContextDataInjector
+```
+
+This is a Log4j component property and must be configured before Log4j initializes, for example via
+a JVM system property:
+
+```shell
+-Dlog4j2.ContextDataInjector=io.opentelemetry.instrumentation.log4j.appender.v2_17.OpenTelemetryAppenderContextDataInjector
+```
+
+or in a `log4j2.component.properties` file on the classpath. It cannot be configured reliably from
+`log4j2.xml`.
+
+With the component property set, the `log4j2.xml` configuration can use normal Log4j async logger
+configuration:
+
+```xml
+<Configuration status="WARN">
+  <Appenders>
+    <OpenTelemetry name="OpenTelemetryAppender"/>
+  </Appenders>
+
+  <Loggers>
+    <AsyncRoot level="info">
+      <AppenderRef ref="OpenTelemetryAppender"/>
+    </AsyncRoot>
+  </Loggers>
+</Configuration>
+```
+
+If your application already configures a custom `log4j2.ContextDataInjector`, configure it as the
+OpenTelemetry injector's delegate:
+
+```properties
+log4j2.ContextDataInjector=io.opentelemetry.instrumentation.log4j.appender.v2_17.OpenTelemetryAppenderContextDataInjector
+otel.instrumentation.log4j-appender.context-data-injector.delegate=com.example.CustomContextDataInjector
+```
+
+The OpenTelemetry injector will call the delegate injector first, then add the OpenTelemetry
+`Context` to the Log4j event context data.
+
+This adds an internal `otel.internal.context` context data entry to carry the OpenTelemetry `Context`.
+Applications that render all Log4j context data, for example with `%X` or JSON layouts, should
+exclude this key from log output because its value is not stable and may change without notice.
+
 [source code attributes]: https://github.com/open-telemetry/semantic-conventions/blob/main/docs/general/attributes.md#source-code-attributes

instrumentation/log4j/log4j-appender-2.17/library/build.gradle.kts

@@ -6,6 +6,7 @@ dependencies {
   library("org.apache.logging.log4j:log4j-core:2.17.0")
   annotationProcessor("org.apache.logging.log4j:log4j-core:2.17.0")
 
+  // to be removed in 3.0
   implementation(project(":instrumentation:log4j:log4j-context-data:log4j-context-data-2.17:library-autoconfigure"))
 
   testImplementation(project(":instrumentation:log4j:log4j-appender-2.17:testing"))
@@ -26,7 +27,10 @@ tasks {
   val testAsyncLogger by registering(Test::class) {
     testClassesDirs = sourceSets.test.get().output.classesDirs
     classpath = sourceSets.test.get().runtimeClasspath
-    jvmArgs("-DLog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector")
+    jvmArgs(
+      "-DLog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector",
+      "-Dlog4j2.ContextDataInjector=io.opentelemetry.instrumentation.log4j.appender.v2_17.OpenTelemetryAppenderContextDataInjector",
+    )
   }
 
   val testStableSemconv by registering(Test::class) {

instrumentation/log4j/log4j-appender-2.17/library/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/OpenTelemetryAppender.java

@@ -5,6 +5,7 @@
 
 package io.opentelemetry.instrumentation.log4j.appender.v2_17;
 
+import static io.opentelemetry.instrumentation.log4j.appender.v2_17.internal.ContextDataKeys.OTEL_CONTEXT_DATA_KEY;
 import static java.util.Collections.emptyList;
 import static java.util.concurrent.TimeUnit.MILLISECONDS;
 import static java.util.concurrent.TimeUnit.NANOSECONDS;
@@ -52,6 +53,7 @@
 import org.apache.logging.log4j.core.config.plugins.PluginBuilderFactory;
 import org.apache.logging.log4j.core.time.Instant;
 import org.apache.logging.log4j.message.MapMessage;
+import org.apache.logging.log4j.status.StatusLogger;
 import org.apache.logging.log4j.util.ReadOnlyStringMap;
 
 @Plugin(
@@ -67,8 +69,10 @@ public class OpenTelemetryAppender extends AbstractAppender {
 
   private final BlockingQueue<LogEventToReplay> eventsToReplay;
   private final AtomicBoolean replayLimitWarningLogged = new AtomicBoolean();
+  private final AtomicBoolean legacyContextDataWarningLogged = new AtomicBoolean();
   private final ReadWriteLock lock = new ReentrantReadWriteLock();
   private final boolean captureCodeAttributes;
+  private final boolean v3Preview;
 
   /**
    * Installs the {@code openTelemetry} instance on any {@link OpenTelemetryAppender}s identified in
@@ -225,16 +229,16 @@ private OpenTelemetryAppender(
     boolean v3Preview = commonConfig.getBoolean("v3_preview", false);
 
     this.mapper =
-        new LogEventMapper<>(
-            ContextDataAccessorImpl.INSTANCE,
+        createMapper(
             captureExperimentalAttributes,
             captureCodeAttributes,
             captureMapMessageAttributes,
             captureMarkerAttribute,
-            splitAndFilterBlanksAndNulls(captureContextDataAttributes),
+            captureContextDataAttributes,
             v3Preview);
     this.openTelemetry = openTelemetry;
     this.captureCodeAttributes = captureCodeAttributes;
+    this.v3Preview = v3Preview;
     if (numLogsCapturedBeforeOtelInstall != 0) {
       this.eventsToReplay = new ArrayBlockingQueue<>(numLogsCapturedBeforeOtelInstall);
     } else {
@@ -252,6 +256,23 @@ private static List<String> splitAndFilterBlanksAndNulls(@Nullable String value)
         .collect(toList());
   }
 
+  private static LogEventMapper<ReadOnlyStringMap> createMapper(
+      boolean captureExperimentalAttributes,
+      boolean captureCodeAttributes,
+      boolean captureMapMessageAttributes,
+      boolean captureMarkerAttribute,
+      @Nullable String captureContextDataAttributes,
+      boolean v3Preview) {
+    return new LogEventMapper<>(
+        ContextDataAccessorImpl.INSTANCE,
+        captureExperimentalAttributes,
+        captureCodeAttributes,
+        captureMapMessageAttributes,
+        captureMarkerAttribute,
+        splitAndFilterBlanksAndNulls(captureContextDataAttributes),
+        v3Preview);
+  }
+
   /**
    * Configures the {@link OpenTelemetry} used to append logs. This MUST be called for the appender
    * to function. See {@link #install(OpenTelemetry)} for simple installation option.
@@ -280,6 +301,7 @@ private void resetAppenderForTest() {
       openTelemetry = null;
       eventsToReplay.clear();
       replayLimitWarningLogged.set(false);
+      legacyContextDataWarningLogged.set(false);
     } finally {
       writeLock.unlock();
     }
@@ -325,28 +347,7 @@ private void emit(OpenTelemetry openTelemetry, LogEvent event) {
     LogRecordBuilder builder =
         openTelemetry.getLogsBridge().loggerBuilder(instrumentationName).build().logRecordBuilder();
     ReadOnlyStringMap contextData = event.getContextData();
-    Context context = Context.current();
-    // when using async logger we'll be executing on a different thread than what started logging
-    // reconstruct the context from context data
-    if (context == Context.root()) {
-      ContextDataAccessor<ReadOnlyStringMap> contextDataAccessor = ContextDataAccessorImpl.INSTANCE;
-      ContextDataKeys contextDataKeys = ContextDataKeys.create(openTelemetry);
-      String traceId = contextDataAccessor.getValue(contextData, contextDataKeys.getTraceIdKey());
-      String spanId = contextDataAccessor.getValue(contextData, contextDataKeys.getSpanIdKey());
-      String traceFlags =
-          contextDataAccessor.getValue(contextData, contextDataKeys.getTraceFlags());
-      if (traceId != null && spanId != null && traceFlags != null) {
-        context =
-            Context.root()
-                .with(
-                    Span.wrap(
-                        SpanContext.create(
-                            traceId,
-                            spanId,
-                            TraceFlags.fromHex(traceFlags, 0),
-                            TraceState.getDefault())));
-      }
-    }
+    Context context = getContext(openTelemetry, event, contextData);
 
     mapper.mapLogEvent(
         builder,
@@ -369,18 +370,85 @@ private void emit(OpenTelemetry openTelemetry, LogEvent event) {
     builder.emit();
   }
 
+  private Context getContext(
+      OpenTelemetry openTelemetry, LogEvent event, ReadOnlyStringMap contextData) {
+    Object context = contextData.getValue(OTEL_CONTEXT_DATA_KEY);
+    if (context instanceof Context) {
+      return (Context) context;
+    }
+    Context currentContext = Context.current();
+    if (currentContext != Context.root()) {
+      return currentContext;
+    }
+
+    if (!v3Preview) {
+      // when using async logger we'll be executing on a different thread than what started logging
+      // reconstruct the context from context data
+      ContextDataAccessor<ReadOnlyStringMap> contextDataAccessor = ContextDataAccessorImpl.INSTANCE;
+      ContextDataKeys contextDataKeys = ContextDataKeys.create(openTelemetry);
+      String traceId = contextDataAccessor.getValue(contextData, contextDataKeys.getTraceIdKey());
+      String spanId = contextDataAccessor.getValue(contextData, contextDataKeys.getSpanIdKey());
+      String traceFlags =
+          contextDataAccessor.getValue(contextData, contextDataKeys.getTraceFlags());
+      if (traceId != null && spanId != null && traceFlags != null) {
+        warnIfUsingLegacyContextDataForAsyncLoggers(event);
+        return Context.root()
+            .with(
+                Span.wrap(
+                    SpanContext.create(
+                        traceId,
+                        spanId,
+                        TraceFlags.fromHex(traceFlags, 0),
+                        TraceState.getDefault())));
+      }
+    }
+    return currentContext;
+  }
+
+  private void warnIfUsingLegacyContextDataForAsyncLoggers(LogEvent event) {
+    if (!wasLoggedOnDifferentThread(event)) {
+      return;
+    }
+    if (legacyContextDataWarningLogged.getAndSet(true)) {
+      return;
+    }
+    StatusLogger.getLogger()
+        .warn(
+            "OpenTelemetry Log4j appender is recovering span context from Log4j context data "
+                + "for an event logged on another thread. This compatibility behavior only "
+                + "propagates span context and will be removed in 3.0. Configure "
+                + "log4j2.ContextDataInjector="
+                + OpenTelemetryAppenderContextDataInjector.class.getName()
+                + " to propagate the full OpenTelemetry Context for async loggers.");
+  }
+
+  private static boolean wasLoggedOnDifferentThread(LogEvent event) {
+    long eventThreadId = event.getThreadId();
+    // Only treat this as async handoff when Log4j captured a usable, different thread id.
+    return eventThreadId > 0 && eventThreadId != Thread.currentThread().getId();
+  }
+
   private enum ContextDataAccessorImpl implements ContextDataAccessor<ReadOnlyStringMap> {
     INSTANCE;
 
     @Override
     @Nullable
     public String getValue(ReadOnlyStringMap contextData, String key) {
-      return contextData.getValue(key);
+      Object value = contextData.getValue(key);
+      if (value instanceof String) {
+        return (String) value;
+      }
+      return null;
     }
 
     @Override
     public void forEach(ReadOnlyStringMap contextData, BiConsumer<String, String> action) {
-      contextData.forEach(action::accept);
+      contextData.forEach(
+          (key, value) -> {
+            if (value instanceof String) {
+              action.accept(key, (String) value);
+            }
+          });
     }
   }
 }

instrumentation/log4j/log4j-appender-2.17/library/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/OpenTelemetryAppenderContextDataInjector.java

@@ -0,0 +1,101 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+package io.opentelemetry.instrumentation.log4j.appender.v2_17;
+
+import static io.opentelemetry.instrumentation.log4j.appender.v2_17.internal.ContextDataKeys.OTEL_CONTEXT_DATA_KEY;
+
+import io.opentelemetry.context.Context;
+import java.util.List;
+import org.apache.logging.log4j.ThreadContext;
+import org.apache.logging.log4j.core.ContextDataInjector;
+import org.apache.logging.log4j.core.config.Property;
+import org.apache.logging.log4j.core.impl.ContextDataFactory;
+import org.apache.logging.log4j.core.impl.ThreadContextDataInjector;
+import org.apache.logging.log4j.core.util.Loader;
+import org.apache.logging.log4j.spi.CopyOnWrite;
+import org.apache.logging.log4j.spi.DefaultThreadContextMap;
+import org.apache.logging.log4j.spi.ReadOnlyThreadContextMap;
+import org.apache.logging.log4j.status.StatusLogger;
+import org.apache.logging.log4j.util.PropertiesUtil;
+import org.apache.logging.log4j.util.ReadOnlyStringMap;
+import org.apache.logging.log4j.util.StringMap;
+
+/**
+ * Injects the full OpenTelemetry {@link Context} into Log4j event context data for async logger
+ * handoff.
+ *
+ * <p>This uses Log4j's ContextDataInjector extension point instead of ContextDataProvider because
+ * the appender needs to carry the {@link Context} object itself, not only string key/value pairs.
+ * Although Log4j 2.17 added ContextDataProvider.supplyStringMap(), Log4j does not call it for every
+ * thread context map. In web-app mode, which is enabled by default when the Servlet API is on the
+ * classpath, Log4j disables thread locals and uses DefaultThreadContextMap. That path calls
+ * ContextDataProvider.supplyContextData(), which is limited to Map&lt;String, String&gt;.
+ *
+ * <p>By delegating to Log4j's selected injector first and then adding the {@link Context} object to
+ * the resulting {@link StringMap}, this works for DefaultThreadContextMap, copy-on-write, and
+ * garbage-free thread context maps.
+ */
+public final class OpenTelemetryAppenderContextDataInjector implements ContextDataInjector {
+
+  static final String DELEGATE_CONTEXT_DATA_INJECTOR_PROPERTY =
+      "otel.instrumentation.log4j-appender.context-data-injector.delegate";
+
+  private final ContextDataInjector delegate = createDelegateInjector();
+
+  @Override
+  public StringMap injectContextData(List<Property> properties, StringMap reusable) {
+    Context context = Context.current();
+    if (context == Context.root()) {
+      return delegate.injectContextData(properties, reusable);
+    }
+    StringMap contextData = delegate.injectContextData(properties, reusable);
+    if (contextData.isFrozen()) {
+      contextData = ContextDataFactory.createContextData(contextData);
+    }
+    contextData.putValue(OTEL_CONTEXT_DATA_KEY, context);
+    return contextData;
+  }
+
+  @Override
+  public ReadOnlyStringMap rawContextData() {
+    Context context = Context.current();
+    if (context == Context.root()) {
+      return delegate.rawContextData();
+    }
+    StringMap contextData = ContextDataFactory.createContextData(delegate.rawContextData());
+    contextData.putValue(OTEL_CONTEXT_DATA_KEY, context);
+    return contextData;
+  }
+
+  private static ContextDataInjector createDelegateInjector() {
+    String className =
+        PropertiesUtil.getProperties().getStringProperty(DELEGATE_CONTEXT_DATA_INJECTOR_PROPERTY);
+    if (className != null) {
+      try {
+        if (className.equals(OpenTelemetryAppenderContextDataInjector.class.getName())) {
+          throw new IllegalArgumentException("Delegate injector cannot be this injector");
+        }
+        return Loader.newCheckedInstanceOf(className, ContextDataInjector.class);
+      } catch (Exception e) {
+        StatusLogger.getLogger()
+            .warn(
+                "Could not create configured ContextDataInjector delegate '{}'; ignoring delegate override",
+                className,
+                e);
+      }
+    }
+
+    // Mirror Log4j's ContextDataInjectorFactory#createDefaultInjector() selection.
+    ReadOnlyThreadContextMap threadContextMap = ThreadContext.getThreadContextMap();
+    if (threadContextMap == null || threadContextMap instanceof DefaultThreadContextMap) {
+      return new ThreadContextDataInjector.ForDefaultThreadContextMap();
+    }
+    if (threadContextMap instanceof CopyOnWrite) {
+      return new ThreadContextDataInjector.ForCopyOnWriteThreadContextMap();
+    }
+    return new ThreadContextDataInjector.ForGarbageFreeThreadContextMap();
+  }
+}

instrumentation/log4j/log4j-appender-2.17/library/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/internal/ContextDataKeys.java

@@ -0,0 +1,17 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+package io.opentelemetry.instrumentation.log4j.appender.v2_17.internal;
+
+/**
+ * This class is internal and is hence not for public use. Its APIs are unstable and can change at
+ * any time.
+ */
+public final class ContextDataKeys {
+
+  public static final String OTEL_CONTEXT_DATA_KEY = "otel.internal.context";
+
+  private ContextDataKeys() {}
+}