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(); } - + } diff --git a/hadoop-project/pom.xml b/hadoop-project/pom.xml index b809cdb8248e0e..d59a8dccc19dbe 100644 --- a/hadoop-project/pom.xml +++ b/hadoop-project/pom.xml @@ -188,7 +188,7 @@ -Xmx4096m -Xss4m -XX:+HeapDumpOnOutOfMemoryError ${extraJavaTestArgs} - 3.5.3 + 3.6.0 ${maven-surefire-plugin.version} ${maven-surefire-plugin.version} diff --git a/hadoop-yarn-project/hadoop-yarn/hadoop-yarn-applications/hadoop-yarn-applications-catalog/hadoop-yarn-applications-catalog-webapp/pom.xml b/hadoop-yarn-project/hadoop-yarn/hadoop-yarn-applications/hadoop-yarn-applications-catalog/hadoop-yarn-applications-catalog-webapp/pom.xml index 724a91431c188c..9b5d3c14551cbd 100644 --- a/hadoop-yarn-project/hadoop-yarn/hadoop-yarn-applications/hadoop-yarn-applications-catalog/hadoop-yarn-applications-catalog-webapp/pom.xml +++ b/hadoop-yarn-project/hadoop-yarn/hadoop-yarn-applications/hadoop-yarn-applications-catalog/hadoop-yarn-applications-catalog-webapp/pom.xml @@ -283,6 +283,13 @@ hadoop-common + + org.apache.hadoop + hadoop-common + test-jar + test + + org.apache.hadoop hadoop-auth diff --git a/hadoop-yarn-project/hadoop-yarn/hadoop-yarn-applications/hadoop-yarn-services/hadoop-yarn-services-core/pom.xml b/hadoop-yarn-project/hadoop-yarn/hadoop-yarn-applications/hadoop-yarn-services/hadoop-yarn-services-core/pom.xml index d25c60def8cc91..d2b2253417a660 100644 --- a/hadoop-yarn-project/hadoop-yarn/hadoop-yarn-applications/hadoop-yarn-services/hadoop-yarn-services-core/pom.xml +++ b/hadoop-yarn-project/hadoop-yarn/hadoop-yarn-applications/hadoop-yarn-services/hadoop-yarn-services-core/pom.xml @@ -167,6 +167,13 @@ hadoop-common + + org.apache.hadoop + hadoop-common + test-jar + test + + org.apache.hadoop hadoop-annotations