HADOOP-19964. Restore TimedOutTestsListener thread dumps on test timeout.

hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/test/GenericTestUtils.java

@@ -399,12 +399,23 @@ public static void waitFor(final Supplier<Boolean> 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());
     }
   }
 

hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/test/TestTimedOutTestsListener.java

@@ -17,16 +17,21 @@
  */
 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;
 
 import org.junit.jupiter.api.Test;
 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;