Implement MDC auto-instrumentation for log4j1 (#1211)

instrumentation/log4j/log4j-1.2/log4j-1.2.gradle

@@ -0,0 +1,24 @@
+apply from: "$rootDir/gradle/instrumentation.gradle"
+
+muzzle {
+  pass {
+    group = "log4j"
+    module = "log4j"
+    versions = "[1.2,)"
+  }
+}
+
+dependencies {
+  // 1.2 introduces MDC and there's no version earlier than 1.2.4 available
+  library group: 'log4j', name: 'log4j', version: '1.2.4'
+}
+
+configurations {
+  // In order to test the real log4j library we need to remove the log4j transitive
+  // dependency 'log4j-over-slf4j' brought in by :testing-common which would shadow
+  // the log4j module under test using a proxy to slf4j instead.
+  testImplementation.exclude group: 'org.slf4j', module: 'log4j-over-slf4j'
+
+  // See: https://stackoverflow.com/a/9047963/2749853
+  testImplementation.exclude group: 'javax.jms', module: 'jms'
+}

instrumentation/log4j/log4j-1.2/src/main/java/io/opentelemetry/instrumentation/auto/log4j/v1_2/Log4j1Instrumentation.java

@@ -0,0 +1,72 @@
+/*
+ * 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.auto.log4j.v1_2;
+
+import static java.util.Collections.singletonMap;
+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 com.google.auto.service.AutoService;
+import io.opentelemetry.instrumentation.auto.api.InstrumentationContext;
+import io.opentelemetry.javaagent.tooling.Instrumenter;
+import io.opentelemetry.trace.Span;
+import io.opentelemetry.trace.TracingContextUtils;
+import java.util.Map;
+import net.bytebuddy.asm.Advice;
+import net.bytebuddy.description.method.MethodDescription;
+import net.bytebuddy.description.type.TypeDescription;
+import net.bytebuddy.matcher.ElementMatcher;
+import org.apache.log4j.spi.LoggingEvent;
+
+@AutoService(Instrumenter.class)
+public class Log4j1Instrumentation extends Instrumenter.Default {
+  public Log4j1Instrumentation() {
+    super("log4j1", "log4j");
+  }
+
+  @Override
+  public ElementMatcher<? super TypeDescription> typeMatcher() {
+    return named("org.apache.log4j.Category");
+  }
+
+  @Override
+  public Map<String, String> contextStore() {
+    return singletonMap("org.apache.log4j.spi.LoggingEvent", Span.class.getName());
+  }
+
+  @Override
+  public Map<? extends ElementMatcher<? super MethodDescription>, String> transformers() {
+    return singletonMap(
+        isMethod()
+            .and(isPublic())
+            .and(named("callAppenders"))
+            .and(takesArguments(1))
+            .and(takesArgument(0, named("org.apache.log4j.spi.LoggingEvent"))),
+        Log4j1Instrumentation.class.getName() + "$CallAppendersAdvice");
+  }
+
+  public static class CallAppendersAdvice {
+    @Advice.OnMethodEnter(suppress = Throwable.class)
+    public static void onEnter(@Advice.Argument(0) LoggingEvent event) {
+      InstrumentationContext.get(LoggingEvent.class, Span.class)
+          .put(event, TracingContextUtils.getCurrentSpan());
+    }
+  }
+}

instrumentation/log4j/log4j-1.2/src/main/java/io/opentelemetry/instrumentation/auto/log4j/v1_2/Log4j1LoggingEventInstrumentation.java

@@ -0,0 +1,147 @@
+/*
+ * 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.auto.log4j.v1_2;
+
+import static java.util.Collections.singletonMap;
+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 com.google.auto.service.AutoService;
+import io.opentelemetry.instrumentation.auto.api.InstrumentationContext;
+import io.opentelemetry.javaagent.tooling.Instrumenter;
+import io.opentelemetry.trace.Span;
+import io.opentelemetry.trace.SpanContext;
+import java.util.HashMap;
+import java.util.Hashtable;
+import java.util.Map;
+import net.bytebuddy.asm.Advice;
+import net.bytebuddy.description.method.MethodDescription;
+import net.bytebuddy.description.type.TypeDescription;
+import net.bytebuddy.matcher.ElementMatcher;
+import org.apache.log4j.MDC;
+import org.apache.log4j.spi.LoggingEvent;
+
+@AutoService(Instrumenter.class)
+public class Log4j1LoggingEventInstrumentation extends Instrumenter.Default {
+  public Log4j1LoggingEventInstrumentation() {
+    super("log4j1", "log4j");
+  }
+
+  @Override
+  public ElementMatcher<? super TypeDescription> typeMatcher() {
+    return named("org.apache.log4j.spi.LoggingEvent");
+  }
+
+  @Override
+  public Map<String, String> contextStore() {
+    return singletonMap("org.apache.log4j.spi.LoggingEvent", Span.class.getName());
+  }
+
+  @Override
+  public Map<? extends ElementMatcher<? super MethodDescription>, String> transformers() {
+    Map<ElementMatcher.Junction<MethodDescription>, String> transformers = new HashMap<>();
+
+    transformers.put(
+        isMethod()
+            .and(isPublic())
+            .and(named("getMDC"))
+            .and(takesArguments(1))
+            .and(takesArgument(0, String.class)),
+        Log4j1LoggingEventInstrumentation.class.getName() + "$GetMdcAdvice");
+
+    transformers.put(
+        isMethod().and(isPublic()).and(named("getMDCCopy")).and(takesArguments(0)),
+        Log4j1LoggingEventInstrumentation.class.getName() + "$GetMdcCopyAdvice");
+
+    return transformers;
+  }
+
+  public static class GetMdcAdvice {
+    @Advice.OnMethodExit(suppress = Throwable.class)
+    public static void onExit(
+        @Advice.This LoggingEvent event,
+        @Advice.Argument(0) String key,
+        @Advice.Return(readOnly = false) Object value) {
+      if ("traceId".equals(key) || "spanId".equals(key) || "sampled".equals(key)) {
+        if (value != null) {
+          // Assume already instrumented event if traceId/spanId/sampled is present.
+          return;
+        }
+
+        Span span = InstrumentationContext.get(LoggingEvent.class, Span.class).get(event);
+        if (span == null || !span.getContext().isValid()) {
+          return;
+        }
+
+        SpanContext spanContext = span.getContext();
+        switch (key) {
+          case "traceId":
+            value = spanContext.getTraceIdAsHexString();
+            break;
+          case "spanId":
+            value = spanContext.getSpanIdAsHexString();
+            break;
+          case "sampled":
+            if (spanContext.isSampled()) {
+              value = "true";
+            }
+            break;
+        }
+      }
+    }
+  }
+
+  public static class GetMdcCopyAdvice {
+    @SuppressWarnings({"unchecked", "rawtypes"})
+    @Advice.OnMethodEnter(suppress = Throwable.class)
+    public static void onEnter(
+        @Advice.This LoggingEvent event,
+        @Advice.FieldValue(value = "mdcCopyLookupRequired", readOnly = false) boolean copyRequired,
+        @Advice.FieldValue(value = "mdcCopy", readOnly = false) Hashtable mdcCopy) {
+      // this advice basically replaces the original method
+
+      if (copyRequired) {
+        copyRequired = false;
+
+        Hashtable mdc = new Hashtable();
+
+        Hashtable originalMdc = MDC.getContext();
+        if (originalMdc != null) {
+          mdc.putAll(originalMdc);
+        }
+
+        // Assume already instrumented event if traceId is present.
+        if (!mdc.contains("traceId")) {
+          Span span = InstrumentationContext.get(LoggingEvent.class, Span.class).get(event);
+          if (span != null && span.getContext().isValid()) {
+            SpanContext spanContext = span.getContext();
+            mdc.put("traceId", spanContext.getTraceIdAsHexString());
+            mdc.put("spanId", spanContext.getSpanIdAsHexString());
+            if (spanContext.isSampled()) {
+              mdc.put("sampled", "true");
+            }
+          }
+        }
+
+        mdcCopy = mdc;
+      }
+    }
+  }
+}

instrumentation/log4j/log4j-1.2/src/test/groovy/ListAppender.groovy

@@ -0,0 +1,40 @@
+/*
+ * 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.
+ */
+
+import org.apache.log4j.AppenderSkeleton
+import org.apache.log4j.spi.LoggingEvent
+
+class ListAppender extends AppenderSkeleton {
+  static events = new ArrayList<LoggingEvent>()
+
+  @Override
+  protected void append(LoggingEvent loggingEvent) {
+    events.add(loggingEvent)
+  }
+
+  @Override
+  boolean requiresLayout() {
+    return false
+  }
+
+  @Override
+  void close() {
+  }
+
+  static clearEvents() {
+    events.clear()
+  }
+}

instrumentation/log4j/log4j-1.2/src/test/groovy/Log4j1MdcTest.groovy

@@ -0,0 +1,88 @@
+/*
+ * 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.
+ */
+
+import io.opentelemetry.auto.test.AgentTestRunner
+import io.opentelemetry.auto.test.utils.TraceUtils
+import io.opentelemetry.trace.TracingContextUtils
+import org.apache.log4j.LogManager
+
+class Log4j1MdcTest extends AgentTestRunner {
+  def cleanup() {
+    ListAppender.clearEvents()
+  }
+
+  def "no ids when no span"() {
+    given:
+    def logger = LogManager.getLogger('TestLogger')
+
+    when:
+    logger.info("log message 1")
+    logger.info("log message 2")
+
+    then:
+    def events = ListAppender.events
+
+    events.size() == 2
+    events[0].message == "log message 1"
+    events[0].getMDC("traceId") == null
+    events[0].getMDC("spanId") == null
+    events[0].getMDC("traceFlags") == null
+
+    events[1].message == "log message 2"
+    events[1].getMDC("traceId") == null
+    events[1].getMDC("spanId") == null
+    events[1].getMDC("traceFlags") == null
+  }
+
+  def "ids when span"() {
+    given:
+    def logger = LogManager.getLogger('TestLogger')
+
+    when:
+    def span1 = TraceUtils.runUnderTrace("test") {
+      logger.info("log message 1")
+      TracingContextUtils.currentSpan
+    }
+
+    logger.info("log message 2")
+
+    def span2 = TraceUtils.runUnderTrace("test 2") {
+      logger.info("log message 3")
+      TracingContextUtils.currentSpan
+    }
+
+    then:
+    def events = ListAppender.events
+
+    events.size() == 3
+    events[0].message == "log message 1"
+    events[0].getMDC("traceId") == span1.context.traceIdAsHexString
+    events[0].getMDC("spanId") == span1.context.spanIdAsHexString
+    events[0].getMDC("sampled") == "true"
+
+    events[1].message == "log message 2"
+    events[1].getMDC("traceId") == null
+    events[1].getMDC("spanId") == null
+    events[1].getMDC("sampled") == null
+
+    events[2].message == "log message 3"
+    // this explicit getMDCCopy() call here is to make sure that whole instrumentation is tested
+    events[2].getMDCCopy()
+    events[2].getMDC("traceId") == span2.context.traceIdAsHexString
+    events[2].getMDC("spanId") == span2.context.spanIdAsHexString
+    events[2].getMDC("sampled") == "true"
+  }
+}

instrumentation/log4j/log4j-1.2/src/test/resources/log4j.properties

@@ -0,0 +1,2 @@
+log4j.rootLogger=INFO, LIST
+log4j.appender.LIST=ListAppender

settings.gradle

@@ -126,6 +126,7 @@ include ':instrumentation:kubernetes-client-7.0'
 include ':instrumentation:lettuce:lettuce-4.0'
 include ':instrumentation:lettuce:lettuce-5.0'
 include ':instrumentation:lettuce:lettuce-5.1'
+include ':instrumentation:log4j:log4j-1.2'
 include ':instrumentation:log4j:log4j-2.13.2:library'
 include ':instrumentation:logback:logback-1.0.0:auto'
 include ':instrumentation:logback:logback-1.0.0:library'