🪞 9979 - Record detailed instrumentation errors during tests (#10300)

ExceptionHandlers: Fix code in bytecode comment

InstrumentationContext: be more explicit about the reasons for failure

Add instrumentation error details on test failures

This puts the details front and center in the test summary and is
much easier than hunting back through log messages.

Note: In InstrumentationErrors, errors are only recorded when
enableRecordingAndReset has been called. This is only done from the
InstrumentationSpecification test specification, so we don't need
to worry about the ArrayList growing without bounds in production.
I considered adding a limit to the ArrayList, but opted not to for
simplicity. I also wanted to avoid silently discarding some errors.

Check for blocked instrumentation in tests

If there is a blocked instrumentation, the test will fail and the
failure message will include the same information that is logged
from MuzzleCheck.

Fail fast on muzzle or instrumentation errors

revert asserting muzzle failures in instrumentation tests

Avoid allocating a stack argument if errors are not recorded

Merge branch 'master' into community-pr-9979

Merge branch 'master' into community-pr-9979

Merge branch 'master' into community-pr-9979

Rework recording of detailed instrumentation errors
* Can be toggled on/off with feature-flag (on for InstrumentationSpecification)
* Zero-impact when the detailed instrumentation error feature is off
* Allow recording of errors indirectly via InstrumentationSpecification
* Reverted change to trace asserts (we shouldn't mix concerns in asserts)

Merge remote-tracking branch 'origin/master' into community-pr-9979

Update comment

Update ClassFileTransformerListener to use InstrumentationErrors

Clean-up reporting of instrumentation errors (installation vs per-test)

Enable detailed instrumentation errors for AbstractInstrumentationTest

Fix metadata/supported-configurations.json

Reset InstrumentationErrors before setupSpec

Co-authored-by: amarziali <andrea.marziali@datadoghq.com>
Co-authored-by: deejgregor <dj@gregor.com>
Co-authored-by: devflow.devflow-routing-intake <devflow.devflow-routing-intake@kubernetes.us1.ddbuild.io>

Author: 4 people

dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/InstrumentationContext.java

@@ -24,7 +24,10 @@ private InstrumentationContext() {}
   public static <K, C> ContextStore<K, C> get(
       final Class<K> keyClass, final Class<C> contextClass) {
     throw new RuntimeException(
-        "Calls to this method will be rewritten by Instrumentation Context Provider (e.g. FieldBackedProvider)");
+        "Calls to this method will be rewritten by Instrumentation Context Provider (e.g. FieldBackedProvider)."
+            + " If you get this exception, this method has not been rewritten."
+            + " Ensure instrumentation class has a contextStore method and the call to InstrumentationContext.get happens directly in an instrumentation Advice class."
+            + " See how_instrumentations_work.md for details.");
   }
 
   /**
@@ -35,6 +38,9 @@ public static <K, C> ContextStore<K, C> get(
    */
   public static <K, C> ContextStore<K, C> get(final String keyClass, final String contextClass) {
     throw new RuntimeException(
-        "Calls to this method will be rewritten by Instrumentation Context Provider (e.g. FieldBackedProvider)");
+        "Calls to this method will be rewritten by Instrumentation Context Provider (e.g. FieldBackedProvider)."
+            + " If you get this exception, this method has not been rewritten."
+            + " Ensure instrumentation class has a contextStore method and the call to InstrumentationContext.get happens directly in an instrumentation Advice class."
+            + " See how_instrumentations_work.md for details.");
   }
 }

dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/InstrumentationErrors.java

@@ -1,21 +1,61 @@
 package datadog.trace.bootstrap;
 
+import java.io.PrintWriter;
+import java.io.StringWriter;
+import java.util.List;
+import java.util.concurrent.CopyOnWriteArrayList;
 import java.util.concurrent.atomic.AtomicLong;
 
 public class InstrumentationErrors {
   private static final AtomicLong COUNTER = new AtomicLong();
 
-  public static long getErrorCount() {
-    return COUNTER.get();
+  private static final class Detailed {
+    static final List<String> ERRORS = new CopyOnWriteArrayList<>();
   }
 
-  @SuppressWarnings("unused")
-  public static void incrementErrorCount() {
+  private static volatile boolean detailed;
+
+  /** Record an error occurred without any detail about it. */
+  public static void recordError() {
+    COUNTER.incrementAndGet();
+  }
+
+  /** Record an error occurred, including its stack trace. */
+  public static Throwable recordError(Throwable error) {
     COUNTER.incrementAndGet();
+    StringWriter detail = new StringWriter();
+    error.printStackTrace(new PrintWriter(detail));
+    Detailed.ERRORS.add(detail.toString());
+    detailed = true;
+    return error; // keep throwable at top of the stack
   }
 
   // Visible for testing
-  public static void resetErrorCount() {
+  public static void resetErrors() {
     COUNTER.set(0);
+    if (detailed) {
+      Detailed.ERRORS.clear();
+      detailed = false;
+    }
+  }
+
+  /**
+   * @return {@code true} if no errors were recorded; otherwise {@code false}
+   */
+  public static boolean noErrors() {
+    return COUNTER.get() == 0;
+  }
+
+  /**
+   * @return a human-readable description of the errors recorded so far
+   */
+  public static String describeErrors() {
+    StringBuilder buf = new StringBuilder().append(COUNTER.get()).append(" instrumentation errors");
+    if (detailed) {
+      for (String error : Detailed.ERRORS) {
+        buf.append("\n---\n").append(error);
+      }
+    }
+    return buf.toString();
   }
 }

dd-java-agent/agent-tooling/src/main/java/datadog/trace/agent/tooling/bytebuddy/ExceptionHandlers.java

@@ -27,6 +27,8 @@ public class ExceptionHandlers {
             private final Size size = new StackManipulation.Size(-1, 3);
             private final boolean appSecEnabled =
                 InstrumenterConfig.get().getAppSecActivation() != ProductActivation.FULLY_DISABLED;
+            private final boolean detailedErrors =
+                InstrumenterConfig.get().isDetailedInstrumentationErrors();
 
             @Override
             public boolean isValid() {
@@ -43,7 +45,7 @@ public Size apply(final MethodVisitor mv, final Implementation.Context context)
               //
               // BlockingExceptionHandler.rethrowIfBlockingException(t);
               // try {
-              //   InstrumentationErrors.incrementErrorCount();
+              //   InstrumentationErrors.recordError();
               //   org.slf4j.LoggerFactory.getLogger((Class)ExceptionLogger.class)
               //     .debug("Failed to handle exception in instrumentation for ...", t);
               // } catch (Throwable t2) {
@@ -53,7 +55,7 @@ public Size apply(final MethodVisitor mv, final Implementation.Context context)
               //
               // BlockingExceptionHandler.rethrowIfBlockingException(t);
               // try {
-              //   InstrumentationErrors.incrementErrorCount();
+              //   InstrumentationErrors.recordError();
               //   org.slf4j.LoggerFactory.getLogger((Class)ExceptionLogger.class)
               //     .error("Failed to handle exception in instrumentation for ...", t);
               //   System.exit(1);
@@ -76,17 +78,28 @@ public Size apply(final MethodVisitor mv, final Implementation.Context context)
                     Opcodes.INVOKESTATIC,
                     "datadog/trace/bootstrap/blocking/BlockingExceptionHandler",
                     "rethrowIfBlockingException",
-                    "(Ljava/lang/Throwable;)Ljava/lang/Throwable;");
+                    "(Ljava/lang/Throwable;)Ljava/lang/Throwable;",
+                    false);
               }
 
               mv.visitTryCatchBlock(logStart, logEnd, eatException, "java/lang/Throwable");
               mv.visitLabel(logStart);
-              // invoke incrementAndGet on our exception counter
-              mv.visitMethodInsn(
-                  Opcodes.INVOKESTATIC,
-                  "datadog/trace/bootstrap/InstrumentationErrors",
-                  "incrementErrorCount",
-                  "()V");
+              // record instrumentation error
+              if (detailedErrors) {
+                mv.visitMethodInsn(
+                    Opcodes.INVOKESTATIC,
+                    "datadog/trace/bootstrap/InstrumentationErrors",
+                    "recordError",
+                    "(Ljava/lang/Throwable;)Ljava/lang/Throwable;",
+                    false);
+              } else {
+                mv.visitMethodInsn(
+                    Opcodes.INVOKESTATIC,
+                    "datadog/trace/bootstrap/InstrumentationErrors",
+                    "recordError",
+                    "()V",
+                    false);
+              }
               // stack: (top) throwable
               mv.visitLdcInsn(Type.getType("L" + HANDLER_NAME + ";"));
               mv.visitMethodInsn(

dd-java-agent/instrumentation-testing/src/main/groovy/datadog/trace/agent/test/InstrumentationSpecification.groovy

@@ -47,6 +47,7 @@ import datadog.trace.api.Pair
 import datadog.trace.api.ProcessTags
 import datadog.trace.api.TraceConfig
 import datadog.trace.api.config.GeneralConfig
+import datadog.trace.api.config.TraceInstrumentationConfig
 import datadog.trace.api.config.TracerConfig
 import datadog.trace.api.datastreams.AgentDataStreamsMonitoring
 import datadog.trace.api.datastreams.DataStreamsTransactionExtractor
@@ -79,7 +80,6 @@ import java.nio.ByteBuffer
 import java.util.concurrent.ConcurrentHashMap
 import java.util.concurrent.TimeUnit
 import java.util.concurrent.TimeoutException
-import java.util.concurrent.atomic.AtomicInteger
 import net.bytebuddy.agent.ByteBuddyAgent
 import net.bytebuddy.agent.builder.AgentBuilder
 import net.bytebuddy.description.type.TypeDescription
@@ -169,10 +169,6 @@ abstract class InstrumentationSpecification extends DDSpecification implements A
   @Shared
   Set<TypeDescription> TRANSFORMED_CLASSES_TYPES = Sets.newConcurrentHashSet()
 
-  @SuppressWarnings('PropertyName')
-  @Shared
-  AtomicInteger INSTRUMENTATION_ERROR_COUNT = new AtomicInteger(0)
-
   // don't use mocks because it will break too many exhaustive interaction-verifying tests
   @SuppressWarnings('PropertyName')
   @Shared
@@ -353,6 +349,8 @@ abstract class InstrumentationSpecification extends DDSpecification implements A
 
   @SuppressForbidden
   void setupSpec() {
+    InstrumentationErrors.resetErrors()
+
     AgentMeter.registerIfAbsent(
     STATS_D_CLIENT,
     new MonitoringImpl(STATS_D_CLIENT, 10, TimeUnit.SECONDS),
@@ -423,6 +421,9 @@ abstract class InstrumentationSpecification extends DDSpecification implements A
     .hasNext(): "No instrumentation found"
     activeTransformer = AgentInstaller.installBytebuddyAgent(
     INSTRUMENTATION, true, AgentInstaller.getEnabledSystems(), this)
+
+    // check for instrumentation issues during installation
+    assert InstrumentationErrors.noErrors(): InstrumentationErrors.describeErrors()
   }
 
   protected String idGenerationStrategyName() {
@@ -431,12 +432,15 @@ abstract class InstrumentationSpecification extends DDSpecification implements A
 
   /** Override to set config before the agent is installed */
   protected void configurePreAgent() {
+    injectSysConfig(TraceInstrumentationConfig.DETAILED_INSTRUMENTATION_ERRORS, "true")
     injectSysConfig(TracerConfig.SCOPE_ITERATION_KEEP_ALIVE, "1") // don't let iteration spans linger
     injectSysConfig(GeneralConfig.DATA_STREAMS_ENABLED, String.valueOf(isDataStreamsEnabled()))
     injectSysConfig(GeneralConfig.DATA_JOBS_ENABLED, String.valueOf(isDataJobsEnabled()))
   }
 
   void setup() {
+    InstrumentationErrors.resetErrors() // reset for each test
+
     configureLoggingLevels()
 
     assertThreadsEachCleanup = false
@@ -472,7 +476,6 @@ abstract class InstrumentationSpecification extends DDSpecification implements A
     if (forceAppSecActive) {
       ActiveSubsystems.APPSEC_ACTIVE = true
     }
-    InstrumentationErrors.resetErrorCount()
     ProcessTags.reset()
   }
 
@@ -514,7 +517,9 @@ abstract class InstrumentationSpecification extends DDSpecification implements A
       spanFinishLocations.clear()
       originalToTrackingSpan.clear()
     }
-    assert InstrumentationErrors.errorCount == 0
+
+    // check for instrumentation issues while running each test
+    assert InstrumentationErrors.noErrors(): InstrumentationErrors.describeErrors()
   }
 
   private void doCheckRepeatedFinish() {
@@ -556,8 +561,6 @@ abstract class InstrumentationSpecification extends DDSpecification implements A
     cleanupAfterAgent()
 
     // All cleanup should happen before these assertion.  If not, a failing assertion may prevent cleanup
-    assert INSTRUMENTATION_ERROR_COUNT.get() == 0: INSTRUMENTATION_ERROR_COUNT.get() + " Instrumentation errors during test"
-
     assert TRANSFORMED_CLASSES_TYPES.findAll {
       GlobalIgnores.isAdditionallyIgnored(it.getActualName())
     }.isEmpty(): "Transformed classes match global libraries ignore matcher"
@@ -658,9 +661,9 @@ abstract class InstrumentationSpecification extends DDSpecification implements A
       return
     }
 
+    InstrumentationErrors.recordError(throwable)
     println "Unexpected instrumentation error when instrumenting ${typeName} on ${classLoader}"
     throwable.printStackTrace()
-    INSTRUMENTATION_ERROR_COUNT.incrementAndGet()
   }
 
   @Override

dd-java-agent/instrumentation-testing/src/main/java/datadog/trace/agent/test/AbstractInstrumentationTest.java

@@ -13,13 +13,15 @@
 import datadog.trace.agent.tooling.bytebuddy.matcher.ClassLoaderMatchers;
 import datadog.trace.api.Config;
 import datadog.trace.api.IdGenerationStrategy;
+import datadog.trace.bootstrap.InstrumentationErrors;
 import datadog.trace.bootstrap.instrumentation.api.AgentSpan;
 import datadog.trace.bootstrap.instrumentation.api.AgentTracer.TracerAPI;
 import datadog.trace.common.writer.ListWriter;
 import datadog.trace.core.CoreTracer;
 import datadog.trace.core.DDSpan;
 import datadog.trace.core.PendingTrace;
 import datadog.trace.core.TraceCollector;
+import datadog.trace.junit.utils.config.WithConfig;
 import datadog.trace.junit.utils.context.AllowContextTestingExtension;
 import java.lang.instrument.ClassFileTransformer;
 import java.lang.instrument.Instrumentation;
@@ -51,6 +53,7 @@
  *   <li>{@code @AfterAll}: Closes the tracer and removes the agent transformer
  * </ul>
  */
+@WithConfig(key = "detailed.instrumentation.errors", value = "true")
 @ExtendWith({TestClassShadowingExtension.class, AllowContextTestingExtension.class})
 public abstract class AbstractInstrumentationTest {
   static final Instrumentation INSTRUMENTATION = ByteBuddyAgent.getInstrumentation();
@@ -66,6 +69,8 @@ public abstract class AbstractInstrumentationTest {
 
   @BeforeAll
   static void initAll() {
+    InstrumentationErrors.resetErrors();
+
     // If this fails, it's likely the result of another test loading Config before it can be
     // injected into the bootstrap classpath.
     assertNull(Config.class.getClassLoader(), "Config must load on the bootstrap classpath.");
@@ -97,17 +102,24 @@ static void initAll() {
     activeTransformer =
         AgentInstaller.installBytebuddyAgent(
             INSTRUMENTATION, true, AgentInstaller.getEnabledSystems(), transformerListener);
+
+    // check for instrumentation issues during installation
+    assertTrue(InstrumentationErrors.noErrors(), InstrumentationErrors::describeErrors);
   }
 
   @BeforeEach
   public void init() {
+    InstrumentationErrors.resetErrors(); // reset for each test
     tracer.flush();
     writer.start();
   }
 
   @AfterEach
   public void tearDown() {
     tracer.flush();
+
+    // check for instrumentation issues while running each test
+    assertTrue(InstrumentationErrors.noErrors(), InstrumentationErrors::describeErrors);
   }
 
   @AfterAll

dd-java-agent/instrumentation-testing/src/main/java/datadog/trace/agent/test/ClassFileTransformerListener.java

@@ -1,13 +1,12 @@
 package datadog.trace.agent.test;
 
-import static org.junit.jupiter.api.Assertions.assertEquals;
 import static org.junit.jupiter.api.Assertions.assertTrue;
 
 import com.google.common.collect.Sets;
 import datadog.trace.agent.tooling.bytebuddy.matcher.GlobalIgnores;
+import datadog.trace.bootstrap.InstrumentationErrors;
 import de.thetaphi.forbiddenapis.SuppressForbidden;
 import java.util.Set;
-import java.util.concurrent.atomic.AtomicInteger;
 import net.bytebuddy.agent.builder.AgentBuilder;
 import net.bytebuddy.description.type.TypeDescription;
 import net.bytebuddy.dynamic.DynamicType;
@@ -18,7 +17,6 @@ public class ClassFileTransformerListener implements AgentBuilder.Listener {
 
   final Set<String> transformedClassesNames = Sets.newConcurrentHashSet();
   final Set<TypeDescription> transformedClassesTypes = Sets.newConcurrentHashSet();
-  final AtomicInteger instrumentationErrorCount = new AtomicInteger(0);
 
   @Override
   public void onTransformation(
@@ -45,10 +43,10 @@ public void onError(
       return;
     }
 
+    InstrumentationErrors.recordError(throwable);
     System.out.println(
         "Unexpected instrumentation error when instrumenting " + typeName + " on " + classLoader);
     throwable.printStackTrace();
-    instrumentationErrorCount.incrementAndGet();
   }
 
   @Override
@@ -70,9 +68,6 @@ public void onComplete(
   }
 
   public void verify() {
-    // Check instrumentation errors
-    int errorCount = this.instrumentationErrorCount.get();
-    assertEquals(0, errorCount, errorCount + " instrumentation errors during test");
     // Check effectively transformed classes that should have been ignored
     assertTrue(
         this.transformedClassesTypes.stream()

dd-trace-api/src/main/java/datadog/trace/api/config/TraceInstrumentationConfig.java

@@ -15,6 +15,7 @@ public final class TraceInstrumentationConfig {
   public static final String CODE_ORIGIN_MAX_USER_FRAMES = "code.origin.max.user.frames";
   public static final String TRACE_ENABLED = "trace.enabled";
   public static final String INTEGRATIONS_ENABLED = "integrations.enabled";
+  public static final String DETAILED_INSTRUMENTATION_ERRORS = "detailed.instrumentation.errors";
 
   public static final String TRACE_EXTENSIONS_PATH = "trace.extensions.path";