Write every Java test method's log into a separate file

Summary: Write every Java test method's log into a separate file

Test Plan: Jenkins

Reviewers: hector, bogdan, bharat

Reviewed By: bharat

Subscribers: ybase

Differential Revision: https://phabricator.dev.yugabyte.com/D4420

CMakeLists.txt

@@ -153,6 +153,7 @@ function(VALIDATE_COMPILER_TYPE)
     endif()
   endif()
 
+  set(USING_SANITIZERS FALSE PARENT_SCOPE)
   if ("${YB_USE_ASAN}" OR "${YB_USE_TSAN}" OR "${YB_USE_UBSAN}")
     if (NOT "$ENV{YB_COMPILER_TYPE}" STREQUAL "" AND
         NOT "$ENV{YB_COMPILER_TYPE}" STREQUAL "clang")
@@ -164,6 +165,7 @@ function(VALIDATE_COMPILER_TYPE)
               "YB_USE_UBSAN=${YB_USE_UBSAN}")
     endif()
     set(ENV{YB_COMPILER_TYPE} "clang")
+    set(USING_SANITIZERS TRUE PARENT_SCOPE)
   endif()
 
   if ("$ENV{YB_COMPILER_TYPE}" STREQUAL "")
@@ -615,6 +617,8 @@ endif()
 # distinguishes further into BSD vs everything else, but we probably do not care further.
 if(APPLE)
   ADD_CXX_FLAGS("-DOS_MACOSX")
+elseif(NOT "${USING_SANITIZERS}")
+  ADD_LINKER_FLAGS("-Wl,--no-undefined -Wl,--no-allow-shlib-undefined")
 endif()
 
 # Explicitly disable the new gcc5 ABI. Until clang supports abi tags [1], any
@@ -852,7 +856,6 @@ else()
   string(SUBSTRING "${YB_LINK}" 0 1 YB_LINK)
 endif()
 
-message("YB_USE_ASAN=${YB_USE_ASAN}")
 # Clang does not support using ASAN and TSAN simultaneously.
 if ("${YB_USE_ASAN}" AND "${YB_USE_TSAN}")
   message(SEND_ERROR "Can only enable one of ASAN or TSAN at a time")

java/yb-client/src/test/java/org/yb/BaseYBTest.java

@@ -14,6 +14,9 @@
  */
 package org.yb;
 
+import org.apache.log4j.Appender;
+import org.apache.log4j.ConsoleAppender;
+import org.apache.log4j.LogManager;
 import org.junit.Rule;
 import org.junit.rules.ExpectedException;
 import org.junit.rules.TestRule;
@@ -27,8 +30,7 @@
 import java.io.FileOutputStream;
 import java.io.IOException;
 import java.io.PrintStream;
-import java.util.HashMap;
-import java.util.Map;
+import java.util.Enumeration;
 import java.util.concurrent.TimeUnit;
 
 /**
@@ -37,9 +39,18 @@
 public class BaseYBTest {
   private static final Logger LOG = LoggerFactory.getLogger(BaseYBTest.class);
 
+  // Global static variables to keep track of the current test class/method and index (1, 2, 3,
+  // etc.) within the test class. We are assuming that we don't not try to run multiple tests in
+  // parallel in the same JVM.
+
   private static String currentTestClassName;
   private static String currentTestMethodName;
 
+  private static final int UNDEFINED_TEST_METHOD_INDEX = -1;
+
+  // We put "001", "002", etc. in per-test log files.
+  private static int testMethodIndex = UNDEFINED_TEST_METHOD_INDEX;
+
   @Rule
   public final Timeout METHOD_TIMEOUT = new Timeout(
       TestUtils.adjustTimeoutForBuildType(getTestMethodTimeoutSec()), TimeUnit.SECONDS);
@@ -51,46 +62,101 @@ public class BaseYBTest {
   @Rule
   public final TestRule watcher = new TestWatcher() {
 
-    private Map<String, Long> startTimesMs = new HashMap<>();
+    boolean succeeded;
+    boolean failed;
+    long startTimeMs;
+    Throwable failureException;
 
     private final String descriptionToStr(Description description) {
       return TestUtils.getClassAndMethodStr(description);
     }
 
+    private void switchLogging(Runnable doLogging, Runnable doSwitching) {
+      doLogging.run();
+
+      if (TestUtils.usePerTestLogFiles()) {
+        doSwitching.run();
+
+        // Re-create the "out" appender.
+        org.apache.log4j.Logger rootLogger = LogManager.getRootLogger();
+        Enumeration<Appender> appenders = rootLogger.getAllAppenders();
+        int numAppenders = 0;
+        while (appenders.hasMoreElements()) {
+          Appender appender = appenders.nextElement();
+          if (!appender.getName().equals("out")) {
+            throw new RuntimeException(
+                "Expected to have one appender named 'out' to exist, got " + appender.getName());
+          }
+          numAppenders++;
+        }
+        if (numAppenders != 1) {
+          throw new RuntimeException(
+              "Expected to have one appender named 'out' to exist, got " + numAppenders +
+                  " appenders");
+        }
+        Appender oldOutAppender = LogManager.getRootLogger().getAppender("out");
+        rootLogger.removeAllAppenders();
+
+        Appender appender = new ConsoleAppender(oldOutAppender.getLayout());
+        appender.setName(oldOutAppender.getName());
+        rootLogger.addAppender(appender);
+
+        doLogging.run();
+      }
+    }
+
+    private void resetState() {
+      succeeded = false;
+      failed = false;
+      startTimeMs = 0;
+      failureException = null;
+    }
+
     @Override
     protected void starting(Description description) {
+      if (testMethodIndex == UNDEFINED_TEST_METHOD_INDEX) {
+        testMethodIndex = 1;
+      }
+      resetState();
+      startTimeMs = System.currentTimeMillis();
+
       currentTestClassName = description.getClassName();
       currentTestMethodName = description.getMethodName();
 
-      if (TestUtils.isEnvVarTrue("YB_JAVA_PER_TEST_METHOD_OUTPUT_FILES")) {
-        // An experimental mode with a separate output file for each test method.
-        System.out.flush();
-        System.err.flush();
-        String outputPrefix = TestUtils.getSurefireTestReportPrefix();
-        try {
-          System.setOut(new PrintStream(new FileOutputStream(outputPrefix + "stdout.txt")));
-          System.setErr(new PrintStream(new FileOutputStream(outputPrefix + "stderr.txt")));
-        } catch (IOException ex) {
-          throw new RuntimeException(ex);
-        }
-      }
-
-      // The format of the heading below is important as it is parsed by external test dashboarding
-      // tools.
       String descStr = descriptionToStr(description);
-      TestUtils.printHeading(System.out, "Starting YB Java test: " + descStr);
-      startTimesMs.put(descStr, System.currentTimeMillis());
+
+      switchLogging(
+          () -> {
+            // The format of the heading below is important as it is parsed by external test
+            // dashboarding tools.
+            TestUtils.printHeading(System.out, "Starting YB Java test: " + descStr);
+          },
+          () -> {
+            // Use a separate output file for each test method.
+            String outputPrefix = TestUtils.getTestReportFilePrefix();
+            String stdoutPath = outputPrefix + "stdout.txt";
+            String stderrPath = outputPrefix + "stderr.txt";
+            LOG.info("Writing stdout for test " + descStr + " to " + stdoutPath);
+
+            System.out.flush();
+            System.err.flush();
+            try {
+              System.setOut(new PrintStream(new FileOutputStream(stdoutPath)));
+              System.setErr(new PrintStream(new FileOutputStream(stderrPath)));
+            } catch (IOException ex) {
+              throw new RuntimeException(ex);
+            }
+          });
     }
 
     @Override
     protected void succeeded(Description description) {
-      LOG.info("YB Java test succeeded: " + descriptionToStr(description));
       super.succeeded(description);
     }
 
     @Override
     protected void failed(Throwable e, Description description) {
-      LOG.error("YB Java test failed: " + descriptionToStr(description), e);
+      failureException = e;
       super.failed(e, description);
     }
 
@@ -101,15 +167,30 @@ protected void failed(Throwable e, Description description) {
     protected void finished(Description description) {
       // The format of the heading below is important as it is parsed by external test dashboarding
       // tools.
-      String descStr = TestUtils.getClassAndMethodStr(description);
-      Long startTimeMs = startTimesMs.get(descStr);
-      if (startTimeMs == null) {
-        LOG.error("Could not identify start time for test " + descStr + " to compute its duration");
-      } else {
-        double elapsedTimeSec = (System.currentTimeMillis() - startTimeMs) / 1000.0;
-        LOG.info("YB Java test " + descStr + String.format(" took %.2f seconds", elapsedTimeSec));
-      }
-      TestUtils.printHeading(System.out, "Finished YB Java test: " + descStr);
+      final String descStr = descriptionToStr(description);
+      switchLogging(
+          () -> {
+            if (succeeded) {
+              LOG.info("YB Java test succeeded: " + descStr);
+            }
+            if (failed) {
+              LOG.error("YB Java test failed: " + descStr, failureException);
+            }
+            if (startTimeMs == 0) {
+              LOG.error("Could not identify start time for test " + descStr + " to compute its " +
+                  "duration");
+            } else {
+              double elapsedTimeSec = (System.currentTimeMillis() - startTimeMs) / 1000.0;
+              LOG.info("YB Java test " + descStr +
+                  String.format(" took %.2f seconds", elapsedTimeSec));
+            }
+            TestUtils.printHeading(System.out, "Finished YB Java test: " + descStr);
+          },
+          () -> {
+            TestUtils.resetDefaultStdOutAndErr();
+          });
+      resetState();
+      testMethodIndex++;
     }
   };
 
@@ -135,4 +216,11 @@ public static String getCurrentTestMethodName() {
     return currentTestMethodName;
   }
 
+  public static int getTestMethodIndex() {
+    if (testMethodIndex == UNDEFINED_TEST_METHOD_INDEX) {
+      throw new RuntimeException("Test method index within the test class not known");
+    }
+    return testMethodIndex;
+  }
+
 }

java/yb-client/src/test/java/org/yb/client/TestUtils.java

@@ -76,6 +76,12 @@ public class TestUtils {
   private static final long WAIT_FOR_TTL_EXTENSION_MS = 100;
 
   private static String NONBLOCKING_RANDOM_DEVICE = "/dev/urandom";
+
+  private static PrintStream defaultStdOut = System.out;
+  private static PrintStream defaultStdErr = System.err;
+
+  private static final boolean DEFAULT_USE_PER_TEST_LOG_FILES = true;
+
   static {
     long seed = System.nanoTime();
     if (new File(NONBLOCKING_RANDOM_DEVICE).exists()) {
@@ -413,18 +419,22 @@ public static void waitFor(Condition condition, long timeoutMs) throws Exception
     }
   }
 
-  public static void printHorizontalLine(PrintStream out) {
+  private static String getHorizontalLine() {
     final StringBuilder horizontalLine = new StringBuilder();
     for (int i = 0; i < 100; ++i) {
       horizontalLine.append("-");
     }
-    out.println(horizontalLine);
+    return horizontalLine.toString();
+  }
+
+  public static String HORIZONTAL_LINE = getHorizontalLine();
+
+  public static void printHorizontalLine(PrintStream out) {
+    out.println(HORIZONTAL_LINE);
   }
 
   public static void printHeading(PrintStream out, String msg) {
-    out.println();
-    printHorizontalLine(out);
-    out.println(msg + "\n");
+    out.println("\n" + HORIZONTAL_LINE + "\n" + msg + "\n" + HORIZONTAL_LINE + "\n");
   }
 
   public static String getClassAndMethodStr(Description description) {
@@ -583,7 +593,7 @@ public static CommandResult runShellCommand(String cmd) throws IOException {
     }
   }
 
-  public static String getSurefireTestReportPrefix() {
+  public static String getTestReportFilePrefix() {
     Class testClass;
     try {
       testClass = Class.forName(BaseYBTest.getCurrentTestClassName());
@@ -606,16 +616,37 @@ public static String getSurefireTestReportPrefix() {
     }
     return new File(
         surefireDir,
-        testClass.getName() + "." + BaseYBTest.getCurrentTestMethodName() + "-output."
+        testClass.getName() + String.format(".%03d.", BaseYBTest.getTestMethodIndex()) +
+            BaseYBTest.getCurrentTestMethodName() + "."
     ).toString();
   }
 
-  public static boolean isEnvVarTrue(String envVarName) {
-    String value = System.getenv(envVarName);
+  public static boolean isStringTrue(String value, boolean defaultValue) {
     if (value == null)
-      return false;
-    value = value.trim();
-    return !value.isEmpty() && !value.equals("0") && !value.equals("no") && !value.equals("false");
+      return defaultValue;
+    value = value.trim().toLowerCase();
+    if (value.isEmpty() || value.equals("auto") || value.equals("default"))
+      return defaultValue;
+    return !value.equals("0") && !value.equals("no") && !value.equals("false");
+  }
+
+  public static boolean isEnvVarTrue(String envVarName, boolean defaultValue) {
+    return isStringTrue(System.getenv(envVarName), defaultValue);
+  }
+
+  public static void resetDefaultStdOutAndErr() {
+    System.setOut(defaultStdOut);
+    System.setErr(defaultStdErr);
+  }
+
+  private static volatile Boolean usePerTestLogFiles = null;
+
+  public static boolean usePerTestLogFiles() {
+    if (usePerTestLogFiles == null) {
+      usePerTestLogFiles = isEnvVarTrue(
+          "YB_JAVA_PER_TEST_LOG_FILES", DEFAULT_USE_PER_TEST_LOG_FILES);
+    }
+    return usePerTestLogFiles.booleanValue();
   }
 
 }

java/yb-client/src/test/java/org/yb/minicluster/MiniYBCluster.java

@@ -78,8 +78,8 @@ public class MiniYBCluster implements AutoCloseable {
 
   public static final int CATALOG_MANAGER_BG_TASK_WAIT_MS = 500;
 
-  // We support 127.0.0.1 - 127.0.0.16 on MAC as loopback IPs.
-  private static final int NUM_LOCALHOSTS_ON_MAC_OS_X = 16;
+  // We expect that 127.0.0.1 - 127.0.0.254 might be present on macOS as loopback IPs.
+  private static final int NUM_LOCALHOSTS_ON_MAC_OS_X = 254;
 
   private static final String TSERVER_MASTER_ADDRESSES_FLAG = "--tserver_master_addrs";
 
@@ -557,7 +557,7 @@ private MiniYBDaemon configureAndStartProcess(MiniYBDaemonType type,
       String fatalDetailsPathPrefix = System.getenv("YB_FATAL_DETAILS_PATH_PREFIX");
       if (fatalDetailsPathPrefix == null) {
         fatalDetailsPathPrefix =
-            TestUtils.getSurefireTestReportPrefix() + "fatal_failure_details";
+            TestUtils.getTestReportFilePrefix() + "fatal_failure_details";
       }
       fatalDetailsPathPrefix += "." + type.shortStr() + "-" + indexForLog + "." + bindIp + "-" +
           "port" + rpcPort;

java/yb-client/src/test/resources/log4j.properties

@@ -30,6 +30,8 @@
 # under the License.
 #
 
+# We expect only one appender to exist, and it must be called "out" and log to stdout.
+# This should be in sync the log file switching logic in BaseYBTest.
 log4j.rootLogger = DEBUG, out
 log4j.appender.out = org.apache.log4j.ConsoleAppender
 log4j.appender.out.layout = org.apache.log4j.PatternLayout

java/yb-cql/src/test/java/org/yb/cql/TestBatchRequest.java

@@ -34,6 +34,7 @@ public class TestBatchRequest extends BaseCQLTest {
 
   @Override
   public int getTestMethodTimeoutSec() {
+    // No need to adjust for TSAN vs. non-TSAN here, it will be done automatically.
     return 180;
   }
 

java/yb-cql/src/test/java/org/yb/cql/TestInsert.java

@@ -31,6 +31,7 @@ public class TestInsert extends BaseCQLTest {
 
   @Override
   public int getTestMethodTimeoutSec() {
+    // No need to adjust for TSAN vs. non-TSAN here, it will be done automatically.
     return 240;
   }
 

java/yb-cql/src/test/java/org/yb/cql/TestKeyspace.java

@@ -80,6 +80,7 @@ public void useKeyspace(String keyspaceName) throws Exception {
   }
 
   public int getTestMethodTimeoutSec() {
+    // No need to adjust for TSAN vs. non-TSAN here, it will be done automatically.
     return 300;
   }