Fail instrumentation tests on logged stack overflows

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

@@ -117,6 +117,7 @@ import spock.lang.Shared
 @TrackScopeContinuations
 abstract class InstrumentationSpecification extends DDSpecification implements AgentBuilder.Listener, ScopeDiagnosticsSpockSupport {
   private static final long TIMEOUT_MILLIS = TimeUnit.SECONDS.toMillis(20)
+  private LoggedStackOverflowCheck loggedStackOverflow
 
   protected static final Instrumentation INSTRUMENTATION = ByteBuddyAgent.getInstrumentation()
 
@@ -468,6 +469,8 @@ abstract class InstrumentationSpecification extends DDSpecification implements A
 
     configureLoggingLevels()
 
+    loggedStackOverflow = new LoggedStackOverflowCheck()
+
     assertThreadsEachCleanup = false
 
     closePrevious(true) // in case the previous test left a lingering iteration span
@@ -552,6 +555,7 @@ abstract class InstrumentationSpecification extends DDSpecification implements A
 
         // check for instrumentation issues while running each test
         assert InstrumentationErrors.noErrors(): InstrumentationErrors.describeErrors()
+        loggedStackOverflow?.check()
       } catch (Throwable cleanupFailure) {
         if (scopeDiagnosticsFailure != null) {
           cleanupFailure.addSuppressed(scopeDiagnosticsFailure)
@@ -562,6 +566,7 @@ abstract class InstrumentationSpecification extends DDSpecification implements A
         throw scopeDiagnosticsFailure
       }
     } finally {
+      loggedStackOverflow?.close()
       if (scopeDiagnosticsSuiteEnabled()) {
         ScopeDiagnostics.startRecording()
       }

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

@@ -73,6 +73,7 @@ public abstract class AbstractInstrumentationTest {
   protected static ListWriter writer;
   private static ClassFileTransformer activeTransformer;
   private static ClassFileTransformerListener transformerListener;
+  private LoggedStackOverflowCheck loggedStackOverflow;
 
   @BeforeAll
   static void initAll() {
@@ -116,17 +117,25 @@ static void initAll() {
 
   @BeforeEach
   public void init() {
+    loggedStackOverflow = new LoggedStackOverflowCheck();
     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);
+    try {
+      tracer.flush();
+
+      // check for instrumentation issues while running each test
+      assertTrue(InstrumentationErrors.noErrors(), InstrumentationErrors::describeErrors);
+      loggedStackOverflow.check();
+    } finally {
+      if (loggedStackOverflow != null) {
+        loggedStackOverflow.close();
+      }
+    }
   }
 
   @AfterAll

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

@@ -0,0 +1,100 @@
+package datadog.trace.agent.test;
+
+import java.util.concurrent.atomic.AtomicReference;
+import java.util.logging.Handler;
+import java.util.logging.LogRecord;
+import java.util.logging.Logger;
+import org.slf4j.LoggerFactory;
+
+/** Captures logged stack overflows so framework exception handling cannot silently pass a test. */
+public final class LoggedStackOverflowCheck implements AutoCloseable {
+  private final AtomicReference<StackOverflowError> firstError = new AtomicReference<>();
+  private final Logger julRoot = Logger.getLogger("");
+  private final Handler julHandler =
+      new Handler() {
+        @Override
+        public void publish(LogRecord record) {
+          capture(record.getThrown());
+        }
+
+        @Override
+        public void flush() {}
+
+        @Override
+        public void close() {}
+      };
+  private final Runnable detachLogback;
+
+  public LoggedStackOverflowCheck() {
+    Object factory = LoggerFactory.getILoggerFactory();
+    // Some instrumentation suites deliberately exclude Logback from their runtime classpath.
+    detachLogback =
+        factory.getClass().getName().equals("ch.qos.logback.classic.LoggerContext")
+            ? LogbackCapture.install(factory, this)
+            : () -> {};
+    julRoot.addHandler(julHandler);
+  }
+
+  private void capture(Throwable error) {
+    // Do not format a stack trace or log from the thread whose stack is exhausted. Bound traversal
+    // because frameworks may wrap the error, and Throwable cause chains can contain cycles.
+    for (int depth = 0; error != null && depth < 16; depth++) {
+      if (error instanceof StackOverflowError) {
+        firstError.compareAndSet(null, (StackOverflowError) error);
+        return;
+      }
+      error = error.getCause();
+    }
+  }
+
+  public void check() {
+    StackOverflowError error = firstError.get();
+    if (error != null) {
+      throw new AssertionError("A StackOverflowError was logged during the test", error);
+    }
+  }
+
+  @Override
+  public void close() {
+    julRoot.removeHandler(julHandler);
+    detachLogback.run();
+  }
+
+  private static final class LogbackCapture extends ch.qos.logback.classic.turbo.TurboFilter {
+    private final LoggedStackOverflowCheck check;
+
+    private LogbackCapture(LoggedStackOverflowCheck check) {
+      this.check = check;
+    }
+
+    static Runnable install(Object factory, LoggedStackOverflowCheck check) {
+      ch.qos.logback.classic.LoggerContext context = (ch.qos.logback.classic.LoggerContext) factory;
+      LogbackCapture filter = new LogbackCapture(check);
+      filter.start();
+      context.addTurboFilter(filter);
+      return () -> {
+        context.getTurboFilterList().remove(filter);
+        filter.stop();
+      };
+    }
+
+    @Override
+    public ch.qos.logback.core.spi.FilterReply decide(
+        org.slf4j.Marker marker,
+        ch.qos.logback.classic.Logger logger,
+        ch.qos.logback.classic.Level level,
+        String format,
+        Object[] params,
+        Throwable throwable) {
+      check.capture(throwable);
+      // Logback can extract the trailing throwable from SLF4J arguments after this callback.
+      if (params != null && params.length > 0) {
+        Object last = params[params.length - 1];
+        if (last instanceof Throwable) {
+          check.capture((Throwable) last);
+        }
+      }
+      return ch.qos.logback.core.spi.FilterReply.NEUTRAL;
+    }
+  }
+}

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

@@ -0,0 +1,79 @@
+package datadog.trace.agent.test;
+
+import static org.junit.jupiter.api.Assertions.assertDoesNotThrow;
+import static org.junit.jupiter.api.Assertions.assertSame;
+import static org.junit.jupiter.api.Assertions.assertThrows;
+
+import java.util.logging.Level;
+import java.util.logging.Logger;
+import org.junit.jupiter.api.Test;
+import org.slf4j.LoggerFactory;
+
+class LoggedStackOverflowCheckTest {
+  @Test
+  void julBackgroundErrorFailsOnTheTestThread() throws Exception {
+    StackOverflowError overflow = new StackOverflowError("background JUL error");
+    try (LoggedStackOverflowCheck check = new LoggedStackOverflowCheck()) {
+      Thread background =
+          new Thread(
+              () -> Logger.getLogger(getClass().getName()).log(Level.SEVERE, "caught", overflow));
+      background.start();
+      background.join();
+
+      assertSame(overflow, assertThrows(AssertionError.class, check::check).getCause());
+    }
+  }
+
+  @Test
+  void logbackBackgroundErrorFailsOnTheTestThread() throws Exception {
+    StackOverflowError overflow = new StackOverflowError("background Logback error");
+    try (LoggedStackOverflowCheck check = new LoggedStackOverflowCheck()) {
+      Thread background =
+          new Thread(() -> LoggerFactory.getLogger(getClass()).error("caught", overflow));
+      background.start();
+      background.join();
+
+      assertSame(overflow, assertThrows(AssertionError.class, check::check).getCause());
+    }
+  }
+
+  @Test
+  void capturesWrappedAndParameterizedErrorsAndRetainsTheFirst() {
+    StackOverflowError first = new StackOverflowError("first");
+    try (LoggedStackOverflowCheck check = new LoggedStackOverflowCheck()) {
+      LoggerFactory.getLogger(getClass())
+          .error("caught in {}", "handler", new RuntimeException(first));
+      Logger.getLogger(getClass().getName())
+          .log(Level.SEVERE, "caught", new StackOverflowError("second"));
+
+      assertSame(first, assertThrows(AssertionError.class, check::check).getCause());
+    }
+  }
+
+  @Test
+  void ignoresOrdinaryErrorsAndMessagesMentioningStackOverflow() {
+    RuntimeException first = new RuntimeException();
+    RuntimeException second = new RuntimeException(first);
+    first.initCause(second);
+    try (LoggedStackOverflowCheck check = new LoggedStackOverflowCheck()) {
+      Logger.getLogger(getClass().getName()).log(Level.SEVERE, "StackOverflowError", first);
+      LoggerFactory.getLogger(getClass()).error("java.lang.StackOverflowError");
+
+      assertDoesNotThrow(check::check);
+    }
+  }
+
+  @Test
+  void closeDetachesBothLoggingHooksAndNextTestStartsClean() {
+    LoggedStackOverflowCheck closed = new LoggedStackOverflowCheck();
+    closed.close();
+    StackOverflowError overflow = new StackOverflowError("after close");
+    Logger.getLogger(getClass().getName()).log(Level.SEVERE, "caught", overflow);
+    LoggerFactory.getLogger(getClass()).error("caught", overflow);
+    assertDoesNotThrow(closed::check);
+
+    try (LoggedStackOverflowCheck next = new LoggedStackOverflowCheck()) {
+      assertDoesNotThrow(next::check);
+    }
+  }
+}

docs/how_to_test.md

@@ -48,6 +48,13 @@ The project leverages different types of tests:
 > [!TIP]
 > Most of the instrumented tests and integration tests are instrumentation tests.
 
+### Logged stack overflows
+
+Instrumentation tests fail when JUL or Logback logs a `StackOverflowError` during a test,
+including one caught by a framework on a background thread. The harness retains the error and
+reports it during cleanup even if the response and trace assertions passed. This check does not
+cover errors that are never logged, other logging backends, or a JVM that hangs before cleanup.
+
 ### Forked Tests
 
 Independent of the type of test, test can be run in another (forked) JVM than the one running Gradle.