Implement MDC auto-instrumentation for log4j2

open-telemetry · Sep 16, 2020 · e323d3c · e323d3c
1 parent 594e41e
commit e323d3c
Show file tree

Hide file tree

Showing 7 changed files with 80 additions and 59 deletions.
diff --git a/...n-api/src/main/java/io/opentelemetry/instrumentation/api/log/LoggingContextConstants.java b/...n-api/src/main/java/io/opentelemetry/instrumentation/api/log/LoggingContextConstants.java
@@ -0,0 +1,39 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package io.opentelemetry.instrumentation.api.log;
+
+/**
+ * This class contains several constants used in logging libraries' Mapped Diagnostic Context
+ * instrumentations.
+ *
+ * @see org.slf4j.MDC
+ * @see org.apache.logging.log4j.ThreadContext
+ * @see org.apache.log4j.MDC
+ */
+public final class LoggingContextConstants {
+  /** Key under which the current trace id will be injected into the context data. */
+  public static final String TRACE_ID = "traceId";
+  /** Key under which the current span id will be injected into the context data. */
+  public static final String SPAN_ID = "spanId";
+  /**
+   * Key under which a boolean indicating whether current span is sampled will be injected into the
+   * context data.
+   */
+  public static final String SAMPLED = "sampled";
+
+  private LoggingContextConstants() {}
+}
diff --git a/.../log4j/v2_13_2/Log4j2Instrumentation.java → ...g4j/v2_13_2/Log4j2MdcInstrumentation.java b/.../log4j/v2_13_2/Log4j2Instrumentation.java → ...g4j/v2_13_2/Log4j2MdcInstrumentation.java
@@ -17,30 +17,20 @@
 package io.opentelemetry.instrumentation.auto.log4j.v2_13_2;
 
 import static io.opentelemetry.javaagent.tooling.ClassLoaderMatcher.hasClassesNamed;
-import static net.bytebuddy.matcher.ElementMatchers.isMethod;
-import static net.bytebuddy.matcher.ElementMatchers.isPrivate;
-import static net.bytebuddy.matcher.ElementMatchers.isStatic;
 import static net.bytebuddy.matcher.ElementMatchers.named;
-import static net.bytebuddy.matcher.ElementMatchers.takesArguments;
 
 import com.google.auto.service.AutoService;
-import io.opentelemetry.instrumentation.log4j.v2_13_2.OpenTelemetryContextDataProvider;
 import io.opentelemetry.javaagent.tooling.Instrumenter;
-import java.util.ArrayList;
 import java.util.Collections;
-import java.util.List;
 import java.util.Map;
-import net.bytebuddy.asm.Advice;
 import net.bytebuddy.description.method.MethodDescription;
 import net.bytebuddy.description.type.TypeDescription;
-import net.bytebuddy.implementation.bytecode.assign.Assigner.Typing;
 import net.bytebuddy.matcher.ElementMatcher;
-import org.apache.logging.log4j.core.util.ContextDataProvider;
 
 @AutoService(Instrumenter.class)
-public final class Log4j2Instrumentation extends Instrumenter.Default {
-  public Log4j2Instrumentation() {
-    super("log4j2", "log4j", "log4j2.13.2");
+public final class Log4j2MdcInstrumentation extends Instrumenter.Default {
+  public Log4j2MdcInstrumentation() {
+    super("log4j2", "log4j", "log4j-2.13.2");
   }
 
   @Override
@@ -53,6 +43,13 @@ public ElementMatcher<? super TypeDescription> typeMatcher() {
     return named("org.apache.logging.log4j.core.impl.ThreadContextDataInjector");
   }
 
+  @Override
+  public String[] helperResourceNames() {
+    return new String[] {
+      "META-INF/services/org.apache.logging.log4j.core.util.ContextDataProvider",
+    };
+  }
+
   @Override
   public String[] helperClassNames() {
     return new String[] {
@@ -62,31 +59,7 @@ public String[] helperClassNames() {
 
   @Override
   public Map<? extends ElementMatcher<? super MethodDescription>, String> transformers() {
-    return Collections.singletonMap(
-        isMethod()
-            .and(isPrivate())
-            .and(isStatic())
-            .and(named("getProviders"))
-            .and(takesArguments(0)),
-        Log4j2Instrumentation.class.getName() + "$GetProvidersAdvice");
-  }
-
-  public static class GetProvidersAdvice {
-    @Advice.OnMethodExit(suppress = Throwable.class)
-    public static void onExit(
-        @Advice.Return(typing = Typing.DYNAMIC, readOnly = false)
-            List<ContextDataProvider> providers) {
-      // check if already instrumented
-      for (ContextDataProvider provider : providers) {
-        if (provider instanceof OpenTelemetryContextDataProvider) {
-          return;
-        }
-      }
-
-      List<ContextDataProvider> instrumentedProviders = new ArrayList<>(providers.size() + 1);
-      instrumentedProviders.addAll(providers);
-      instrumentedProviders.add(new OpenTelemetryContextDataProvider());
-      providers = instrumentedProviders;
-    }
+    // Nothing to instrument, injecting helper resource & class is enough
+    return Collections.emptyMap();
   }
 }
diff --git a/instrumentation/log4j/log4j-2.13.2/library/log4j-2.13.2-library.gradle b/instrumentation/log4j/log4j-2.13.2/library/log4j-2.13.2-library.gradle
@@ -7,8 +7,5 @@ apply from: "$rootDir/gradle/instrumentation-library.gradle"
 dependencies {
   library group: 'org.apache.logging.log4j', name: 'log4j-core', version: '2.13.2'
 
-  annotationProcessor deps.autoservice
-  compileOnly deps.autoservice
-
   testImplementation project(':instrumentation:log4j:log4j-2-testing')
 }
diff --git a/...java/io/opentelemetry/instrumentation/log4j/v2_13_2/OpenTelemetryContextDataProvider.java b/...java/io/opentelemetry/instrumentation/log4j/v2_13_2/OpenTelemetryContextDataProvider.java
@@ -16,7 +16,10 @@
 
 package io.opentelemetry.instrumentation.log4j.v2_13_2;
 
-import com.google.auto.service.AutoService;
+import static io.opentelemetry.instrumentation.api.log.LoggingContextConstants.SAMPLED;
+import static io.opentelemetry.instrumentation.api.log.LoggingContextConstants.SPAN_ID;
+import static io.opentelemetry.instrumentation.api.log.LoggingContextConstants.TRACE_ID;
+
 import io.opentelemetry.trace.Span;
 import io.opentelemetry.trace.SpanContext;
 import io.opentelemetry.trace.TracingContextUtils;
@@ -29,7 +32,6 @@
  * Implementation of Log4j 2's {@link ContextDataProvider} which is loaded via SPI. {@link
  * #supplyContextData()} is called when a log entry is created.
  */
-@AutoService(ContextDataProvider.class)
 public class OpenTelemetryContextDataProvider implements ContextDataProvider {
 
   /**
@@ -47,10 +49,10 @@ public Map<String, String> supplyContextData() {
 
     Map<String, String> contextData = new HashMap<>();
     SpanContext spanContext = currentSpan.getContext();
-    contextData.put("traceId", spanContext.getTraceIdAsHexString());
-    contextData.put("spanId", spanContext.getSpanIdAsHexString());
+    contextData.put(TRACE_ID, spanContext.getTraceIdAsHexString());
+    contextData.put(SPAN_ID, spanContext.getSpanIdAsHexString());
     if (spanContext.isSampled()) {
-      contextData.put("sampled", "true");
+      contextData.put(SAMPLED, "true");
     }
     return contextData;
   }

diff --git a/...c/main/resources/META-INF/services/org.apache.logging.log4j.core.util.ContextDataProvider b/...c/main/resources/META-INF/services/org.apache.logging.log4j.core.util.ContextDataProvider
@@ -0,0 +1 @@
+io.opentelemetry.instrumentation.log4j.v2_13_2.OpenTelemetryContextDataProvider
diff --git a/...to/log4j/v2_7/Log4j27Instrumentation.java → ...log4j/v2_7/Log4j27MdcInstrumentation.java b/...to/log4j/v2_7/Log4j27Instrumentation.java → ...log4j/v2_7/Log4j27MdcInstrumentation.java
@@ -16,6 +16,9 @@
 
 package io.opentelemetry.instrumentation.auto.log4j.v2_7;
 
+import static io.opentelemetry.instrumentation.api.log.LoggingContextConstants.SAMPLED;
+import static io.opentelemetry.instrumentation.api.log.LoggingContextConstants.SPAN_ID;
+import static io.opentelemetry.instrumentation.api.log.LoggingContextConstants.TRACE_ID;
 import static io.opentelemetry.javaagent.tooling.ClassLoaderMatcher.hasClassesNamed;
 import static io.opentelemetry.javaagent.tooling.bytebuddy.matcher.AgentElementMatchers.implementsInterface;
 import static net.bytebuddy.matcher.ElementMatchers.isMethod;
@@ -38,9 +41,9 @@
 import org.apache.logging.log4j.util.StringMap;
 
 @AutoService(Instrumenter.class)
-public class Log4j27Instrumentation extends Instrumenter.Default {
-  public Log4j27Instrumentation() {
-    super("log4j2", "log4j", "log4j2.7");
+public class Log4j27MdcInstrumentation extends Instrumenter.Default {
+  public Log4j27MdcInstrumentation() {
+    super("log4j2", "log4j", "log4j-2.7");
   }
 
   @Override
@@ -59,7 +62,7 @@ public Map<? extends ElementMatcher<? super MethodDescription>, String> transfor
         isMethod()
             .and(named("injectContextData"))
             .and(returns(named("org.apache.logging.log4j.util.StringMap"))),
-        Log4j27Instrumentation.class.getName() + "$InjectContextDataAdvice");
+        Log4j27MdcInstrumentation.class.getName() + "$InjectContextDataAdvice");
   }
 
   public static class InjectContextDataAdvice {
@@ -71,15 +74,17 @@ public static void onExit(
         return;
       }
 
-      if (contextData.containsKey("traceId")) {
+      if (contextData.containsKey(TRACE_ID)) {
         // Assume already instrumented event if traceId is present.
         return;
       }
 
       StringMap newContextData = new SortedArrayStringMap(contextData);
-      newContextData.putValue("traceId", currentContext.getTraceId().toLowerBase16());
-      newContextData.putValue("spanId", currentContext.getSpanId().toLowerBase16());
-      newContextData.putValue("traceFlags", currentContext.getTraceFlags().toLowerBase16());
+      newContextData.putValue(TRACE_ID, currentContext.getTraceIdAsHexString());
+      newContextData.putValue(SPAN_ID, currentContext.getSpanIdAsHexString());
+      if (currentContext.isSampled()) {
+        newContextData.putValue(SAMPLED, "true");
+      }
       contextData = newContextData;
     }
   }

diff --git a/.../src/main/java/io/opentelemetry/instrumentation/logback/v1_0_0/OpenTelemetryAppender.java b/.../src/main/java/io/opentelemetry/instrumentation/logback/v1_0_0/OpenTelemetryAppender.java
@@ -16,6 +16,10 @@
 
 package io.opentelemetry.instrumentation.logback.v1_0_0;
 
+import static io.opentelemetry.instrumentation.api.log.LoggingContextConstants.SAMPLED;
+import static io.opentelemetry.instrumentation.api.log.LoggingContextConstants.SPAN_ID;
+import static io.opentelemetry.instrumentation.api.log.LoggingContextConstants.TRACE_ID;
+
 import ch.qos.logback.classic.spi.ILoggingEvent;
 import ch.qos.logback.core.Appender;
 import ch.qos.logback.core.UnsynchronizedAppenderBase;
@@ -40,17 +44,17 @@ public static ILoggingEvent wrapEvent(ILoggingEvent event) {
     }
 
     Map<String, String> eventContext = event.getMDCPropertyMap();
-    if (eventContext != null && eventContext.containsKey("traceId")) {
+    if (eventContext != null && eventContext.containsKey(TRACE_ID)) {
       // Assume already instrumented event if traceId is present.
       return event;
     }
 
     Map<String, String> contextData = new HashMap<>();
     SpanContext spanContext = currentSpan.getContext();
-    contextData.put("traceId", spanContext.getTraceIdAsHexString());
-    contextData.put("spanId", spanContext.getSpanIdAsHexString());
+    contextData.put(TRACE_ID, spanContext.getTraceIdAsHexString());
+    contextData.put(SPAN_ID, spanContext.getSpanIdAsHexString());
     if (spanContext.isSampled()) {
-      contextData.put("sampled", "true");
+      contextData.put(SAMPLED, "true");
     }
 
     if (eventContext == null) {
Original file line number	Diff line number	Diff line change
		@@ -0,0 +1 @@
		io.opentelemetry.instrumentation.log4j.v2_13_2.OpenTelemetryContextDataProvider