From 50aec2fc3da14660c8c550938fd1ca588d85f721 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jose=20Luis=20L=C3=B3pez?= Date: Wed, 19 Aug 2026 14:13:15 +0000 Subject: [PATCH] HADOOP-19964. Restore thread dumps on test timeout. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit GenericTestUtils.waitFor dumps all threads with deadlock analysis to stderr at the moment the wait expires. Its TimeoutException message drops from ~16KB to one line. Sample failure report: 18,223 -> 1,642 bytes. TimedOutTestsListener implements TestExecutionListener. The `listener` provider property the eight poms already carry binds to it once Hadoop moves to Surefire 3.6.0, which accepts platform listeners there (SUREFIRE-1639, apache/maven-surefire#3438). Dormant until then. No pom is touched. The Surefire upgrade is deliberately not part of this change. 3.6.0 initialises the forked JVM's networking before applying systemPropertyVariables, so java.net.preferIPv4Stack stops taking effect and common, mapreduce, hdfs and hdfs-rbf tests fail on dual-stack hosts. Reported upstream as apache/maven-surefire#3456. The upgrade, and the argLine fix it needs, are tracked separately. - -Dhadoop.test.timedout.dump=false disables dumps. - -Dhadoop.test.timedout.dump.limit (default 5) caps them per JVM, with one elision notice. Both entry points share the budget. - The exception records "Thread dump printed to stderr." only when a dump was printed. - The two checkstyle violations the 2012 test file carried are fixed. Not covered: Surefire's fork kill at forkedProcessTimeoutInSeconds (Shutdown.KILL -> Runtime.halt()). HADOOP-19950 captures those reports. Release note: waitFor's TimeoutException message no longer carries the thread dump. Tests: TestTimedOutTestsListener covers timeout detection, the off switch, the dump limit, dumpForTimeout's return value, and waitFor's exact message in all three states — dump printed, dumps off, budget spent, driving the real waitFor. TestGenericTestUtils passes unchanged. Contains content generated by Claude Code. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01RrG4oLaFUcjSuv9Q5zeaZe --- .../apache/hadoop/test/GenericTestUtils.java | 23 +- .../test/TestTimedOutTestsListener.java | 184 +++++++++++++- .../hadoop/test/TimedOutTestsListener.java | 229 ++++++++++++++++-- 3 files changed, 401 insertions(+), 35 deletions(-) diff --git a/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/test/GenericTestUtils.java b/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/test/GenericTestUtils.java index f20a560497894c..85052cab73bddc 100644 --- a/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/test/GenericTestUtils.java +++ b/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/test/GenericTestUtils.java @@ -399,12 +399,23 @@ public static void waitFor(final Supplier check, } if (!result) { - final String exceptionErrorMsg = "Timed out waiting for condition. " - + (org.apache.commons.lang3.StringUtils.isNotEmpty(errorMsg) - ? "Error Message: " + errorMsg : "") - + "\nThread diagnostics:\n" + - TimedOutTestsListener.buildThreadDiagnosticString(); - throw new TimeoutException(exceptionErrorMsg); + // Dump now, while the threads are still hung, rather than leaving it to + // whoever handles the failure later. + boolean dumped = + TimedOutTestsListener.dumpForTimeout("GenericTestUtils.waitFor"); + final StringBuilder exceptionErrorMsg = + new StringBuilder("Timed out waiting for condition."); + if (org.apache.commons.lang3.StringUtils.isNotEmpty(errorMsg)) { + exceptionErrorMsg.append(" Error Message: ").append(errorMsg); + } + // The marker records that a dump was printed, so it is only appended + // when one was: dumpForTimeout refuses when dumps are switched off or + // this JVM's budget is spent. + if (dumped) { + exceptionErrorMsg.append(' ') + .append(TimedOutTestsListener.DUMP_PRINTED_MARKER); + } + throw new TimeoutException(exceptionErrorMsg.toString()); } } diff --git a/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/test/TestTimedOutTestsListener.java b/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/test/TestTimedOutTestsListener.java index 6805dcd2fd4b3b..512ae72178a265 100644 --- a/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/test/TestTimedOutTestsListener.java +++ b/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/test/TestTimedOutTestsListener.java @@ -17,9 +17,12 @@ */ package org.apache.hadoop.test; +import java.io.ByteArrayOutputStream; +import java.io.PrintStream; import java.io.PrintWriter; import java.io.StringWriter; import java.util.concurrent.CyclicBarrier; +import java.util.concurrent.TimeoutException; import java.util.concurrent.locks.Lock; import java.util.concurrent.locks.ReentrantLock; @@ -27,6 +30,8 @@ import org.junit.jupiter.api.Timeout; import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertThrows; import static org.junit.jupiter.api.Assertions.assertTrue; public class TestTimedOutTestsListener { @@ -136,11 +141,16 @@ private void goMonitorDeadlock() { } class Monitor { - String name; - + private final String name; + Monitor(String name) { this.name = name; } + + @Override + public String toString() { + return name; + } } } @@ -152,17 +162,20 @@ public void testThreadDumpAndDeadlocks() throws Exception { String s = null; while (true) { s = TimedOutTestsListener.buildDeadlockInfo(); - if (s != null) + if (s != null) { break; + } Thread.sleep(100); } assertEquals(3, countStringOccurrences(s, "BLOCKED")); RuntimeException failure = - new RuntimeException(TimedOutTestsListener.TEST_TIMED_OUT_PREFIX); + new RuntimeException("test timed out after 1000 milliseconds"); + assertTrue(TimedOutTestsListener.isTimeoutFailure(failure)); StringWriter writer = new StringWriter(); - new TimedOutTestsListener(new PrintWriter(writer)).testFailure(failure); + new TimedOutTestsListener(new PrintWriter(writer)) + .printThreadDump("testThreadDumpAndDeadlocks()"); String out = writer.toString(); assertTrue(out.contains("THREAD DUMP")); @@ -171,6 +184,167 @@ public void testThreadDumpAndDeadlocks() throws Exception { System.out.println(out); } + @Test + @Timeout(value = 30) + public void testDumpDisabledByProperty() { + TimedOutTestsListener.resetDumpCountForTesting(); + System.setProperty(TimedOutTestsListener.DUMP_PROPERTY, "false"); + try { + StringWriter writer = new StringWriter(); + assertFalse( + new TimedOutTestsListener(new PrintWriter(writer)).shouldDump()); + assertEquals("", writer.toString()); + } finally { + System.clearProperty(TimedOutTestsListener.DUMP_PROPERTY); + } + } + + @Test + @Timeout(value = 30) + public void testDumpLimit() { + TimedOutTestsListener.resetDumpCountForTesting(); + System.setProperty(TimedOutTestsListener.DUMP_LIMIT_PROPERTY, "2"); + try { + StringWriter writer = new StringWriter(); + TimedOutTestsListener listener = + new TimedOutTestsListener(new PrintWriter(writer)); + assertTrue(listener.shouldDump()); + assertTrue(listener.shouldDump()); + // Third dump exceeds the limit: refused, with a single elision notice. + assertFalse(listener.shouldDump()); + assertTrue(writer.toString().contains("Thread dump elided")); + // Fourth is refused silently. + int len = writer.toString().length(); + assertFalse(listener.shouldDump()); + assertEquals(len, writer.toString().length()); + } finally { + System.clearProperty(TimedOutTestsListener.DUMP_LIMIT_PROPERTY); + TimedOutTestsListener.resetDumpCountForTesting(); + } + } + + /** + * GenericTestUtils.waitFor prints its own dump when the wait expires, while + * the threads are still hung, and records that in the exception it throws + * so the listener stays quiet. Driving the real waitFor keeps this honest + * if either side ever changes. + */ + @Test + @Timeout(value = 30) + public void testWaitForPrintsItsOwnDump() throws Exception { + TimedOutTestsListener.resetDumpCountForTesting(); + PrintStream oldErr = System.err; + ByteArrayOutputStream captured = new ByteArrayOutputStream(); + TimeoutException failure; + try { + System.setErr(new PrintStream(captured, true)); + failure = assertThrows(TimeoutException.class, + () -> GenericTestUtils.waitFor(() -> false, 10, 50, "still false")); + } finally { + System.setErr(oldErr); + TimedOutTestsListener.resetDumpCountForTesting(); + } + + // The dump goes to stderr, at the moment the wait expired. + String dump = captured.toString(); + assertTrue(dump.contains("PRINTING THREAD DUMP")); + assertTrue(dump.contains("Timed out in: GenericTestUtils.waitFor")); + + // It no longer goes into the message, which used to carry tens of KB. + String message = failure.getMessage(); + assertTrue(TimedOutTestsListener.isTimeoutFailure(failure)); + assertTrue(TimedOutTestsListener.dumpAlreadyPrinted(failure)); + assertFalse(message.contains("java.lang.Thread.State")); + assertEquals("Timed out waiting for condition. Error Message: still false" + + " Thread dump printed to stderr.", message); + + // A timeout carrying no dump of its own is still dumped for. + assertFalse(TimedOutTestsListener.dumpAlreadyPrinted( + new TimeoutException("test timed out after 1000 milliseconds"))); + } + + /** + * The off switch now reaches waitFor too, which the inlined dump it used + * to build was never subject to. With no dump printed, the exception must + * not claim one was. + */ + @Test + @Timeout(value = 30) + public void testWaitForDumpHonoursOffSwitch() throws Exception { + TimedOutTestsListener.resetDumpCountForTesting(); + System.setProperty(TimedOutTestsListener.DUMP_PROPERTY, "false"); + PrintStream oldErr = System.err; + ByteArrayOutputStream captured = new ByteArrayOutputStream(); + TimeoutException failure; + try { + System.setErr(new PrintStream(captured, true)); + failure = assertThrows(TimeoutException.class, + () -> GenericTestUtils.waitFor(() -> false, 10, 50, "no dump here")); + } finally { + System.setErr(oldErr); + System.clearProperty(TimedOutTestsListener.DUMP_PROPERTY); + TimedOutTestsListener.resetDumpCountForTesting(); + } + assertEquals("", captured.toString()); + assertFalse(TimedOutTestsListener.dumpAlreadyPrinted(failure)); + assertEquals("Timed out waiting for condition. Error Message: no dump here", + failure.getMessage()); + } + + /** + * Same when the dump is refused because this JVM's budget is spent: the + * marker would send the reader looking for a dump that is not there. + */ + @Test + @Timeout(value = 30) + public void testWaitForDumpHonoursLimit() throws Exception { + TimedOutTestsListener.resetDumpCountForTesting(); + System.setProperty(TimedOutTestsListener.DUMP_LIMIT_PROPERTY, "1"); + PrintStream oldErr = System.err; + ByteArrayOutputStream captured = new ByteArrayOutputStream(); + TimeoutException first; + TimeoutException second; + try { + System.setErr(new PrintStream(captured, true)); + first = assertThrows(TimeoutException.class, + () -> GenericTestUtils.waitFor(() -> false, 10, 50)); + second = assertThrows(TimeoutException.class, + () -> GenericTestUtils.waitFor(() -> false, 10, 50)); + } finally { + System.setErr(oldErr); + System.clearProperty(TimedOutTestsListener.DUMP_LIMIT_PROPERTY); + TimedOutTestsListener.resetDumpCountForTesting(); + } + assertTrue(TimedOutTestsListener.dumpAlreadyPrinted(first)); + assertFalse(TimedOutTestsListener.dumpAlreadyPrinted(second)); + assertEquals("Timed out waiting for condition.", second.getMessage()); + assertTrue(captured.toString().contains("Thread dump elided")); + } + + /** + * dumpForTimeout reports whether it printed, which is what lets a caller + * decide honestly whether to record the marker. + */ + @Test + @Timeout(value = 30) + public void testDumpForTimeoutReportsWhetherItPrinted() { + TimedOutTestsListener.resetDumpCountForTesting(); + PrintStream oldErr = System.err; + ByteArrayOutputStream captured = new ByteArrayOutputStream(); + try { + System.setErr(new PrintStream(captured, true)); + assertTrue(TimedOutTestsListener.dumpForTimeout("unit test")); + System.setProperty(TimedOutTestsListener.DUMP_PROPERTY, "false"); + assertFalse(TimedOutTestsListener.dumpForTimeout("unit test")); + } finally { + System.setErr(oldErr); + System.clearProperty(TimedOutTestsListener.DUMP_PROPERTY); + TimedOutTestsListener.resetDumpCountForTesting(); + } + assertEquals(1, countStringOccurrences(captured.toString(), + "Timed out in: unit test")); + } + private int countStringOccurrences(String s, String substr) { int n = 0; int index = 0; diff --git a/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/test/TimedOutTestsListener.java b/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/test/TimedOutTestsListener.java index 8a61020ca1ac71..4f075669a29543 100644 --- a/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/test/TimedOutTestsListener.java +++ b/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/test/TimedOutTestsListener.java @@ -28,47 +28,228 @@ import java.text.SimpleDateFormat; import java.util.Date; import java.util.Map; +import java.util.concurrent.TimeoutException; +import java.util.concurrent.atomic.AtomicInteger; +import org.junit.platform.engine.TestExecutionResult; +import org.junit.platform.launcher.TestExecutionListener; +import org.junit.platform.launcher.TestIdentifier; + +import org.apache.hadoop.classification.VisibleForTesting; import org.apache.hadoop.util.StringUtils; /** - * JUnit run listener which prints full thread dump into System.err - * in case a test is failed due to timeout. + * JUnit Platform listener which prints a full thread dump into System.err + * in case a test fails due to timeout. + * + *

Registered through the Surefire {@code listener} provider property, + * which eight module poms carry. That property registers nothing at + * present: the JUnit Platform provider ignores it, which is why the dumps + * stopped at the JUnit 5 migration. It is kept, and this class implements + * {@link TestExecutionListener} rather than the JUnit 4 {@code RunListener} + * it used to, so that the existing wiring starts working with no change to + * Hadoop beyond a Surefire version bump once the provider accepts platform + * listeners there (SUREFIRE-1639, apache/maven-surefire#3438).

+ * + *

Registration through {@code META-INF/services} would work today and is + * deliberately not used: the descriptor would ship in hadoop-common's test + * artifact and auto-activate this listener in every downstream project that + * puts that artifact on a JUnit Platform test classpath.

+ * + *

Until the provider catches up, the dump Hadoop's tests actually get + * comes from {@link #dumpForTimeout}, which {@link GenericTestUtils#waitFor} + * calls directly and which needs no registration at all.

+ * + *

Once active, this listener detects the timeout failures thrown by + * JUnit 5 {@code @Timeout} (a {@link TimeoutException}), by the JUnit 4 + * vintage runner ({@code TestTimedOutException}), and by any other failure + * whose message contains "timed out after". A timeout that dumped for + * itself through {@link #dumpForTimeout} says so in its message, and this + * listener stays quiet for it, so a timeout yields exactly one dump.

+ * + *

Scope: it can only fire for timeouts that surface through JUnit — an + * explicit or default {@code @Timeout}. It cannot fire when Surefire kills + * the fork at {@code forkedProcessTimeoutInSeconds}: the plugin sends the + * fork {@code Shutdown.KILL}, which executes {@code Runtime.halt()} and + * bypasses listeners and shutdown hooks alike. Diagnostics for a fork that + * fails to exit after the tests complete are produced by Surefire + * itself and captured in CI since HADOOP-19950.

+ * + *

Set {@code -Dhadoop.test.timedout.dump=false} to disable the dump, + * and {@code -Dhadoop.test.timedout.dump.limit} (default 5) to bound the + * number of dumps a single JVM prints. Both entry points — this listener + * and {@link #dumpForTimeout} — obey the switch and share the one budget.

*/ -public class TimedOutTestsListener { +public class TimedOutTestsListener implements TestExecutionListener { + + private static final String TIMED_OUT_MARKER = "timed out after"; + + /** + * Sentence a caller of {@link #dumpForTimeout} appends to the exception it + * throws, to record that a dump has already been printed for that failure. + */ + static final String DUMP_PRINTED_MARKER = "Thread dump printed to stderr."; + + private static final String JUNIT4_TIMEOUT_EXCEPTION = + "org.junit.runners.model.TestTimedOutException"; + + /** Set to "false" to disable thread dumps entirely. */ + static final String DUMP_PROPERTY = "hadoop.test.timedout.dump"; + + /** + * Maximum thread dumps a single JVM prints; further ones are elided. This + * listener and {@link #dumpForTimeout} draw on one shared budget, so a JVM + * that has spent it on waitFor timeouts will not dump for a later + * {@code @Timeout} failure. + */ + static final String DUMP_LIMIT_PROPERTY = "hadoop.test.timedout.dump.limit"; + + private static final int DEFAULT_DUMP_LIMIT = 5; - static final String TEST_TIMED_OUT_PREFIX = "test timed out after"; - - private static String INDENT = " "; + private static final AtomicInteger DUMPS = new AtomicInteger(); + + private static final String INDENT = " "; private final PrintWriter output; - + public TimedOutTestsListener() { + // System.err is captured once, deliberately: it pins the real Surefire + // stderr, so a test that leaves System.err redirected cannot swallow the + // dump. this.output = new PrintWriter(System.err); } - + public TimedOutTestsListener(PrintWriter output) { this.output = output; } - public void testFailure(RuntimeException failure) throws Exception { - if (failure != null && failure.getMessage() != null - && failure.getMessage().startsWith(TEST_TIMED_OUT_PREFIX)) { - output.println("====> TEST TIMED OUT. PRINTING THREAD DUMP. <===="); - output.println(); - output.print(buildThreadDiagnosticString()); + @Override + public void executionFinished(TestIdentifier testIdentifier, + TestExecutionResult testExecutionResult) { + if (testExecutionResult.getStatus() + != TestExecutionResult.Status.FAILED) { + return; + } + try { + Throwable failure = + testExecutionResult.getThrowable().orElse(null); + // shouldDump() is checked last: it consumes dump budget, so a + // suppressed dump must not spend any. + if (isTimeoutFailure(failure) && !dumpAlreadyPrinted(failure) + && shouldDump()) { + printThreadDump("Test: " + testIdentifier.getDisplayName()); + } + } catch (RuntimeException e) { + // Diagnostics must never fail the run. + } + } + + /** + * Whether a dump should be printed now: the feature is enabled and this + * JVM's dump limit has not been exhausted. Prints a single elision + * notice when the limit is first exceeded. + */ + boolean shouldDump() { + if (!Boolean.parseBoolean(System.getProperty(DUMP_PROPERTY, "true"))) { + return false; + } + int limit = Integer.getInteger(DUMP_LIMIT_PROPERTY, DEFAULT_DUMP_LIMIT); + int count = DUMPS.incrementAndGet(); + if (count > limit) { + if (count == limit + 1) { + output.println("====> TEST TIMED OUT. Thread dump elided: " + + limit + " dumps already printed by this JVM. <===="); + output.flush(); + } + return false; + } + return true; + } + + @VisibleForTesting + static void resetDumpCountForTesting() { + DUMPS.set(0); + } + + /** + * Whether the given failure is a test timeout. + */ + static boolean isTimeoutFailure(Throwable failure) { + if (failure == null) { + return false; } + if (failure instanceof TimeoutException) { + return true; + } + if (JUNIT4_TIMEOUT_EXCEPTION.equals(failure.getClass().getName())) { + return true; + } + String message = failure.getMessage(); + return message != null && message.contains(TIMED_OUT_MARKER); } - + + /** + * Whether a dump was already printed for this failure when the timeout was + * detected, as {@link GenericTestUtils#waitFor} does. That dump is the + * better one — taken while the threads were still hung, rather than here, + * after the test method and its teardown have unwound — so this listener + * adds nothing. + */ + static boolean dumpAlreadyPrinted(Throwable failure) { + if (failure == null) { + return false; + } + String message = failure.getMessage(); + return message != null && message.contains(DUMP_PRINTED_MARKER); + } + + /** + * Print a thread dump for a timeout detected before JUnit reports the + * failure, so the threads are captured while still hung. Honours the same + * {@value #DUMP_PROPERTY} switch and per-JVM limit as the listener itself, + * so it does not always print. + * + *

A caller that gets {@code true} back should append + * {@link #DUMP_PRINTED_MARKER} to the exception it throws, so a listener + * does not print a second dump for the same failure. On {@code false} it + * must not: nothing was printed, and the same switch and budget that + * refused here will refuse the listener too, so there is no second dump to + * suppress.

+ * + * @param context what timed out, printed above the dump. + * @return whether a dump was printed. + */ + public static boolean dumpForTimeout(String context) { + TimedOutTestsListener listener = new TimedOutTestsListener(); + if (!listener.shouldDump()) { + return false; + } + listener.printThreadDump("Timed out in: " + context); + return true; + } + + /** + * @param context complete line naming what timed out, e.g. "Test: foo()". + */ + void printThreadDump(String context) { + output.println("====> TEST TIMED OUT. PRINTING THREAD DUMP. <===="); + if (context != null) { + output.println(context); + } + output.println(); + output.print(buildThreadDiagnosticString()); + output.flush(); + } + public static String buildThreadDiagnosticString() { StringWriter sw = new StringWriter(); PrintWriter output = new PrintWriter(sw); - - DateFormat dateFormat = new SimpleDateFormat("yyyy-MM-dd hh:mm:ss,SSS"); + + DateFormat dateFormat = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss,SSS"); output.println(String.format("Timestamp: %s", dateFormat.format(new Date()))); output.println(); output.println(buildThreadDump()); - + String deadlocksInfo = buildDeadlockInfo(); if (deadlocksInfo != null) { output.println("====> DEADLOCKS DETECTED <===="); @@ -90,7 +271,7 @@ static String buildThreadDump() { (thread.isDaemon() ? "daemon" : ""), thread.getPriority(), thread.getId(), - Thread.State.WAITING.equals(thread.getState()) ? + Thread.State.WAITING.equals(thread.getState()) ? "in Object.wait()" : StringUtils.toLowerCase(thread.getState().name()), Thread.State.WAITING.equals(thread.getState()) ? @@ -103,28 +284,28 @@ static String buildThreadDump() { } return dump.toString(); } - + static String buildDeadlockInfo() { ThreadMXBean threadBean = ManagementFactory.getThreadMXBean(); long[] threadIds = threadBean.findMonitorDeadlockedThreads(); if (threadIds != null && threadIds.length > 0) { StringWriter stringWriter = new StringWriter(); PrintWriter out = new PrintWriter(stringWriter); - + ThreadInfo[] infos = threadBean.getThreadInfo(threadIds, true, true); for (ThreadInfo ti : infos) { printThreadInfo(ti, out); printLockInfo(ti.getLockedSynchronizers(), out); out.println(); } - + out.close(); return stringWriter.toString(); } else { return null; } } - + private static void printThreadInfo(ThreadInfo ti, PrintWriter out) { // print thread information printThread(ti, out); @@ -170,5 +351,5 @@ private static void printLockInfo(LockInfo[] locks, PrintWriter out) { } out.println(); } - + }