Auto instrumentation for logback event wrapping. (#1180)

README.md

@@ -203,6 +203,7 @@ provide the path to a JAR file including an SPI implementation using the system
 | [khttp](https://khttp.readthedocs.io)                                                                                                 | 0.1+                           |
 | [Kubernetes Client](https://github.com/kubernetes-client/java)                                                                        | 7.0+                           |
 | [Lettuce](https://github.com/lettuce-io/lettuce-core)                                                                                 | 4.0+                           |
+| [Logback](http://logback.qos.ch/)                                                                                                     | 1.0+                           |
 | [MongoDB Drivers](https://mongodb.github.io/mongo-java-driver/)                                                                       | 3.3+                           |
 | [Netty](https://github.com/netty/netty)                                                                                               | 3.8+                           |
 | [OkHttp](https://github.com/square/okhttp/)                                                                                           | 3.0+                           |

instrumentation/logback/logback-1.0.0/auto/logback-1.0.0-auto.gradle

@@ -0,0 +1,20 @@
+apply from: "$rootDir/gradle/instrumentation.gradle"
+
+muzzle {
+  pass {
+    group = "ch.qos.logback"
+    module = "logback-classic"
+    versions = "[1.0.0,1.2.3]"
+  }
+}
+
+dependencies {
+  implementation project(':instrumentation:logback:logback-1.0.0:library')
+
+  library group: 'ch.qos.logback', name: 'logback-classic', version: '1.0.0'
+
+  testImplementation project(':instrumentation:logback:logback-1.0.0:testing')
+
+  // 1.3+ contains breaking changes, check back after it stabilizes.
+  latestDepTestLibrary group: 'ch.qos.logback', name: 'logback-classic', version: '1.2.+'
+}

instrumentation/logback/logback-1.0.0/auto/src/main/java/io/opentelemetry/instrumentation/auto/logback/v1_0_0/LogbackInstrumentation.java

@@ -0,0 +1,76 @@
+/*
+ * 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.logback.v1_0_0;
+
+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 ch.qos.logback.classic.spi.ILoggingEvent;
+import com.google.auto.service.AutoService;
+import io.opentelemetry.instrumentation.logback.v1_0_0.OpenTelemetryAppender;
+import io.opentelemetry.javaagent.tooling.Instrumenter;
+import java.util.Collections;
+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;
+
+@AutoService(Instrumenter.class)
+public class LogbackInstrumentation extends Instrumenter.Default {
+
+  public LogbackInstrumentation() {
+    super("logback");
+  }
+
+  @Override
+  public String[] helperClassNames() {
+    return new String[] {
+      "io.opentelemetry.instrumentation.logback.v1_0_0.OpenTelemetryAppender",
+      "io.opentelemetry.instrumentation.logback.v1_0_0.LoggingEventWrapper",
+      "io.opentelemetry.instrumentation.logback.v1_0_0.UnionMap",
+      "io.opentelemetry.instrumentation.logback.v1_0_0.UnionMap$ConcatenatedSet",
+      "io.opentelemetry.instrumentation.logback.v1_0_0.UnionMap$ConcatenatedSet$ConcatenatedSetIterator",
+    };
+  }
+
+  @Override
+  public ElementMatcher<? super TypeDescription> typeMatcher() {
+    return named("ch.qos.logback.classic.Logger");
+  }
+
+  @Override
+  public Map<? extends ElementMatcher<? super MethodDescription>, String> transformers() {
+    return Collections.singletonMap(
+        isMethod()
+            .and(isPublic())
+            .and(named("callAppenders"))
+            .and(takesArguments(1))
+            .and(takesArgument(0, named("ch.qos.logback.classic.spi.ILoggingEvent"))),
+        LogbackInstrumentation.class.getName() + "$CallAppendersAdvice");
+  }
+
+  public static class CallAppendersAdvice {
+    @Advice.OnMethodEnter
+    public static void onEnter(@Advice.Argument(value = 0, readOnly = false) ILoggingEvent event) {
+      event = OpenTelemetryAppender.wrapEvent(event);
+    }
+  }
+}

instrumentation/logback/logback-1.0.0/auto/src/test/groovy/io/opentelemetry/instrumentation/auto/logback/v1_0_0/LogbackTest.groovy

@@ -0,0 +1,23 @@
+/*
+ * 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.logback.v1_0_0
+
+import io.opentelemetry.auto.test.AgentTestTrait
+import io.opentelemetry.instrumentation.logback.v1_0_0.AbstractLogbackTest
+
+class LogbackTest extends AbstractLogbackTest implements AgentTestTrait {
+}

instrumentation/logback/logback-1.0.0/auto/src/test/resources/logback.xml

@@ -0,0 +1,19 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<configuration>
+  <appender name="LIST" class="ch.qos.logback.core.read.ListAppender" />
+
+  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
+    <encoder>
+      <pattern>%coloredLevel %logger{15} - %message%n%xException{10}</pattern>
+    </encoder>
+  </appender>
+
+  <logger name="test">
+    <level value="info" />
+    <appender-ref ref="LIST" />
+  </logger>
+
+  <root level="debug">
+    <appender-ref ref="STDOUT" />
+  </root>
+</configuration>

instrumentation/logback/logback-1.0.0/library/src/main/java/io/opentelemetry/instrumentation/logback/v1_0_0/OpenTelemetryAppender.java

@@ -33,12 +33,16 @@ public class OpenTelemetryAppender extends UnsynchronizedAppenderBase<ILoggingEv
 
   private final AppenderAttachableImpl<ILoggingEvent> aai = new AppenderAttachableImpl<>();
 
-  @Override
-  protected void append(ILoggingEvent event) {
+  public static ILoggingEvent wrapEvent(ILoggingEvent event) {
     Span currentSpan = TracingContextUtils.getCurrentSpan();
     if (!currentSpan.getContext().isValid()) {
-      aai.appendLoopOnAppenders(event);
-      return;
+      return event;
+    }
+
+    Map<String, String> eventContext = event.getMDCPropertyMap();
+    if (eventContext != null && eventContext.containsKey("traceId")) {
+      // Assume already instrumented event if traceId is present.
+      return event;
     }
 
     Map<String, String> contextData = new HashMap<>();
@@ -47,15 +51,18 @@ protected void append(ILoggingEvent event) {
     contextData.put("spanId", spanContext.getSpanId().toLowerBase16());
     contextData.put("traceFlags", spanContext.getTraceFlags().toLowerBase16());
 
-    Map<String, String> eventContext = event.getMDCPropertyMap();
     if (eventContext == null) {
       eventContext = contextData;
     } else {
       eventContext = new UnionMap<>(eventContext, contextData);
     }
 
-    ILoggingEvent wrapped = new LoggingEventWrapper(event, eventContext);
-    aai.appendLoopOnAppenders(wrapped);
+    return new LoggingEventWrapper(event, eventContext);
+  }
+
+  @Override
+  protected void append(ILoggingEvent event) {
+    aai.appendLoopOnAppenders(wrapEvent(event));
   }
 
   @Override

instrumentation/logback/logback-1.0.0/library/src/main/java/io/opentelemetry/instrumentation/logback/v1_0_0/UnionMap.java

@@ -137,7 +137,7 @@ public Set<Entry<K, V>> entrySet() {
   }
 
   // Member sets must be deduped by caller.
-  private static final class ConcatenatedSet<T> extends AbstractSet<T> {
+  static final class ConcatenatedSet<T> extends AbstractSet<T> {
 
     private final Set<T> first;
     private final Set<T> second;
@@ -183,29 +183,32 @@ public void clear() {
 
     @Override
     public Iterator<T> iterator() {
-      return new Iterator<T>() {
+      return new ConcatenatedSetIterator();
+    }
 
-        final Iterator<T> firstItr = first.iterator();
-        final Iterator<T> secondItr = second.iterator();
+    class ConcatenatedSetIterator implements Iterator<T> {
+      final Iterator<T> firstItr = first.iterator();
+      final Iterator<T> secondItr = second.iterator();
 
-        @Override
-        public boolean hasNext() {
-          return firstItr.hasNext() || secondItr.hasNext();
-        }
+      ConcatenatedSetIterator() {}
 
-        @Override
-        public T next() {
-          if (firstItr.hasNext()) {
-            return firstItr.next();
-          }
-          return secondItr.next();
-        }
+      @Override
+      public boolean hasNext() {
+        return firstItr.hasNext() || secondItr.hasNext();
+      }
 
-        @Override
-        public void remove() {
-          throw new UnsupportedOperationException();
+      @Override
+      public T next() {
+        if (firstItr.hasNext()) {
+          return firstItr.next();
         }
-      };
+        return secondItr.next();
+      }
+
+      @Override
+      public void remove() {
+        throw new UnsupportedOperationException();
+      }
     }
   }
 }

instrumentation/logback/logback-1.0.0/library/src/test/groovy/io/opentelemetry/instrumentation/logback/v1_0_0/LogbackTest.groovy

@@ -16,5 +16,7 @@
 
 package io.opentelemetry.instrumentation.logback.v1_0_0
 
-class LogbackTest extends AbstractLogbackTest {
+import io.opentelemetry.auto.test.InstrumentationTestTrait
+
+class LogbackTest extends AbstractLogbackTest implements InstrumentationTestTrait {
 }

instrumentation/logback/logback-1.0.0/testing/src/main/groovy/io/opentelemetry/instrumentation/logback/v1_0_0/AbstractLogbackTest.groovy

@@ -18,15 +18,15 @@ package io.opentelemetry.instrumentation.logback.v1_0_0
 
 import ch.qos.logback.classic.spi.ILoggingEvent
 import ch.qos.logback.core.read.ListAppender
+import io.opentelemetry.auto.test.InstrumentationSpecification
 import io.opentelemetry.auto.test.utils.TraceUtils
 import io.opentelemetry.trace.Span
 import io.opentelemetry.trace.TracingContextUtils
 import org.slf4j.Logger
 import org.slf4j.LoggerFactory
 import spock.lang.Shared
-import spock.lang.Specification
 
-abstract class AbstractLogbackTest extends Specification {
+abstract class AbstractLogbackTest extends InstrumentationSpecification {
 
   private static final Logger logger = LoggerFactory.getLogger("test")
 
@@ -35,8 +35,15 @@ abstract class AbstractLogbackTest extends Specification {
 
   def setupSpec() {
     ch.qos.logback.classic.Logger logbackLogger = (ch.qos.logback.classic.Logger) logger
-    listAppender = (logbackLogger.getAppender("OTEL") as OpenTelemetryAppender)
-      .getAppender("LIST") as ListAppender<ILoggingEvent>
+    def topLevelListAppender = logbackLogger.getAppender("LIST")
+    if (topLevelListAppender != null) {
+      // Auto instrumentation test.
+      listAppender = topLevelListAppender as ListAppender<ILoggingEvent>
+    } else {
+      // Library instrumentation test.
+      listAppender = (logbackLogger.getAppender("OTEL") as OpenTelemetryAppender)
+        .getAppender("LIST") as ListAppender<ILoggingEvent>
+    }
   }
 
   def setup() {

settings.gradle

@@ -121,6 +121,7 @@ include ':instrumentation:lettuce:lettuce-4.0'
 include ':instrumentation:lettuce:lettuce-5.0'
 include ':instrumentation:lettuce:lettuce-5.1'
 include ':instrumentation:log4j:log4j-2.13.2:library'
+include ':instrumentation:logback:logback-1.0.0:auto'
 include ':instrumentation:logback:logback-1.0.0:library'
 include ':instrumentation:logback:logback-1.0.0:testing'
 include ':instrumentation:mongo:mongo-3.1'