From 4cf71e860076a0ffe806ebe4305480014cfde983 Mon Sep 17 00:00:00 2001 From: Yury Gribkov Date: Fri, 30 Oct 2026 16:57:12 -0700 Subject: [PATCH] Fail instrumentation tests on logged stack overflows --- .../test/InstrumentationSpecification.groovy | 5 + .../test/AbstractInstrumentationTest.java | 17 ++- .../agent/test/LoggedStackOverflowCheck.java | 100 ++++++++++++++++++ .../test/LoggedStackOverflowCheckTest.java | 79 ++++++++++++++ docs/how_to_test.md | 7 ++ 5 files changed, 204 insertions(+), 4 deletions(-) create mode 100644 dd-java-agent/instrumentation-testing/src/main/java/datadog/trace/agent/test/LoggedStackOverflowCheck.java create mode 100644 dd-java-agent/instrumentation-testing/src/test/java/datadog/trace/agent/test/LoggedStackOverflowCheckTest.java diff --git a/dd-java-agent/instrumentation-testing/src/main/groovy/datadog/trace/agent/test/InstrumentationSpecification.groovy b/dd-java-agent/instrumentation-testing/src/main/groovy/datadog/trace/agent/test/InstrumentationSpecification.groovy index 38904cdd717..be29073e943 100644 --- a/dd-java-agent/instrumentation-testing/src/main/groovy/datadog/trace/agent/test/InstrumentationSpecification.groovy +++ b/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() } diff --git a/dd-java-agent/instrumentation-testing/src/main/java/datadog/trace/agent/test/AbstractInstrumentationTest.java b/dd-java-agent/instrumentation-testing/src/main/java/datadog/trace/agent/test/AbstractInstrumentationTest.java index e11722d6a76..b2f208d27a7 100644 --- a/dd-java-agent/instrumentation-testing/src/main/java/datadog/trace/agent/test/AbstractInstrumentationTest.java +++ b/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,6 +117,7 @@ static void initAll() { @BeforeEach public void init() { + loggedStackOverflow = new LoggedStackOverflowCheck(); InstrumentationErrors.resetErrors(); // reset for each test tracer.flush(); writer.start(); @@ -123,10 +125,17 @@ public void init() { @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 diff --git a/dd-java-agent/instrumentation-testing/src/main/java/datadog/trace/agent/test/LoggedStackOverflowCheck.java b/dd-java-agent/instrumentation-testing/src/main/java/datadog/trace/agent/test/LoggedStackOverflowCheck.java new file mode 100644 index 00000000000..bb76c658b8b --- /dev/null +++ b/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 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; + } + } +} diff --git a/dd-java-agent/instrumentation-testing/src/test/java/datadog/trace/agent/test/LoggedStackOverflowCheckTest.java b/dd-java-agent/instrumentation-testing/src/test/java/datadog/trace/agent/test/LoggedStackOverflowCheckTest.java new file mode 100644 index 00000000000..3ea0e93a3ac --- /dev/null +++ b/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); + } + } +} diff --git a/docs/how_to_test.md b/docs/how_to_test.md index 87876f75168..9339f45693a 100644 --- a/docs/how_to_test.md +++ b/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.