Update JUnitRunner to include java.util.logging messages in stdout / …

…stderr

Summary:
Currently, `JUnitRunner` plays tricks with `System.out` and `System.err`.
That means all log messages written to the standard `java.util.logging` are lost
even if we properly set up logging.

This diff explicitly registers a log `Handler` with `java.util.logging`
before each test to write test log data to the redirected `System.out` and
`System.err` so we can get more information about what happened when a test
fails.

Test Plan: New integration test included. `ant java-test -Dtest.class=LoggingIntegrationTest`

src/com/facebook/buck/junit/BUCK

@@ -17,6 +17,7 @@ java_library(
     'BuckBlockJUnit4ClassRunner.java',
     'DelegateRunnerWithTimeout.java',
     'DelegateRunNotifier.java',
+    'JulLogFormatter.java',
     'JUnitMain.java',
     'JUnitRunner.java',
     'SameThreadFailOnTimeout.java',

src/com/facebook/buck/junit/JUnitRunner.java

@@ -35,10 +35,17 @@
 import org.junit.runners.model.RunnerBuilder;
 
 import java.io.ByteArrayOutputStream;
+import java.io.OutputStream;
 import java.io.PrintStream;
 import java.util.ArrayList;
 import java.util.Collections;
 import java.util.List;
+import java.util.logging.Formatter;
+import java.util.logging.Handler;
+import java.util.logging.Level;
+import java.util.logging.LogManager;
+import java.util.logging.Logger;
+import java.util.logging.StreamHandler;
 
 /**
  * Class that runs a set of JUnit tests and writes the results to a directory.
@@ -48,6 +55,10 @@
  * not to interfere with the results of the test.
  */
 public final class JUnitRunner extends BaseRunner {
+
+  static final String JUL_DEBUG_LOGS_HEADER = "====DEBUG LOGS====\n\n";
+  static final String JUL_ERROR_LOGS_HEADER = "====ERROR LOGS====\n\n";
+
   public JUnitRunner() {
   }
 
@@ -261,6 +272,9 @@ private static class TestListener extends RunListener {
     private final List<TestResult> results;
     private PrintStream originalOut, originalErr, stdOutStream, stdErrStream;
     private ByteArrayOutputStream rawStdOutBytes, rawStdErrBytes;
+    private ByteArrayOutputStream julLogBytes, julErrLogBytes;
+    private Handler julLogHandler;
+    private Handler julErrLogHandler;
     private Result result;
     private RunListener resultListener;
     private Failure assumptionFailure;
@@ -280,13 +294,27 @@ public void testStarted(Description description) throws Exception {
       originalErr = System.err;
       rawStdOutBytes = new ByteArrayOutputStream();
       rawStdErrBytes = new ByteArrayOutputStream();
+      julLogBytes = new ByteArrayOutputStream();
+      julErrLogBytes = new ByteArrayOutputStream();
       stdOutStream = new PrintStream(
           rawStdOutBytes, true /* autoFlush */, ENCODING);
       stdErrStream = new PrintStream(
           rawStdErrBytes, true /* autoFlush */, ENCODING);
       System.setOut(stdOutStream);
       System.setErr(stdErrStream);
 
+      // Listen to any java.util.logging messages reported by the test and write them to
+      // julLogBytes / julErrLogBytes.
+      Logger rootLogger = LogManager.getLogManager().getLogger("");
+
+      if (rootLogger != null) {
+        rootLogger.setLevel(Level.FINE);
+      }
+
+      JulLogFormatter formatter = new JulLogFormatter();
+      julLogHandler = addStreamHandler(rootLogger, julLogBytes, formatter, Level.FINE);
+      julErrLogHandler = addStreamHandler(rootLogger, julErrLogBytes, formatter, Level.WARNING);
+
       // Prepare single-test result.
       result = new Result();
       resultListener = result.createListener();
@@ -305,6 +333,15 @@ public void testFinished(Description description) throws Exception {
       System.setOut(originalOut);
       System.setErr(originalErr);
 
+      // Flush any debug logs and remove the handlers.
+      Logger rootLogger = LogManager.getLogManager().getLogger("");
+
+      flushAndRemoveLogHandler(rootLogger, julLogHandler);
+      julLogHandler = null;
+
+      flushAndRemoveLogHandler(rootLogger, julErrLogHandler);
+      julErrLogHandler = null;
+
       // Get the stdout/stderr written during the test as strings.
       stdOutStream.flush();
       stdErrStream.flush();
@@ -339,16 +376,28 @@ public void testFinished(Description description) throws Exception {
         type = ResultType.FAILURE;
       }
 
-      String stdOut = rawStdOutBytes.size() == 0 ? null : rawStdOutBytes.toString(ENCODING);
-      String stdErr = rawStdErrBytes.size() == 0 ? null : rawStdErrBytes.toString(ENCODING);
+      StringBuilder stdOut = new StringBuilder();
+      stdOut.append(rawStdOutBytes.toString(ENCODING));
+      if (type == ResultType.FAILURE && julLogBytes.size() > 0) {
+        stdOut.append('\n');
+        stdOut.append(JUL_DEBUG_LOGS_HEADER);
+        stdOut.append(julLogBytes.toString(ENCODING));
+      }
+      StringBuilder stdErr = new StringBuilder();
+      stdErr.append(rawStdErrBytes.toString(ENCODING));
+      if (type == ResultType.FAILURE && julErrLogBytes.size() > 0) {
+        stdErr.append('\n');
+        stdErr.append(JUL_ERROR_LOGS_HEADER);
+        stdErr.append(julErrLogBytes.toString(ENCODING));
+      }
 
       results.add(new TestResult(className,
           methodName,
           result.getRunTime(),
           type,
           failure == null ? null : failure.getException(),
-          stdOut,
-          stdErr));
+          stdOut.length() == 0 ? null : stdOut.toString(),
+          stdErr.length() == 0 ? null : stdErr.toString()));
     }
 
     /**
@@ -404,5 +453,30 @@ private void recordUnpairedFailure(Failure failure) {
           null,
           null));
     }
+
+    private static Handler addStreamHandler(
+        Logger rootLogger,
+        OutputStream stream,
+        Formatter formatter,
+        Level level) {
+      Handler result;
+      if (rootLogger != null) {
+        result = new StreamHandler(stream, formatter);
+        result.setLevel(level);
+        rootLogger.addHandler(result);
+      } else {
+        result = null;
+      }
+      return result;
+    }
+
+    private static void flushAndRemoveLogHandler(Logger rootLogger, Handler handler) {
+      if (handler != null) {
+        handler.flush();
+      }
+      if (rootLogger != null && handler != null) {
+        rootLogger.removeHandler(handler);
+      }
+    }
   }
 }

src/com/facebook/buck/junit/JulLogFormatter.java

@@ -0,0 +1,100 @@
+/*
+ * Copyright 2015-present Facebook, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License"); you may
+ * not use this file except in compliance with the License. You may obtain
+ * a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+ * WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+ * License for the specific language governing permissions and limitations
+ * under the License.
+ */
+
+package com.facebook.buck.junit;
+
+import java.io.PrintWriter;
+import java.io.StringWriter;
+import java.text.SimpleDateFormat;
+import java.util.Date;
+import java.util.Locale;
+import java.util.TimeZone;
+import java.util.logging.Formatter;
+import java.util.logging.Level;
+import java.util.logging.LogRecord;
+
+public class JulLogFormatter extends Formatter {
+  private static final int ERROR_LEVEL = Level.SEVERE.intValue();
+  private static final int WARN_LEVEL = Level.WARNING.intValue();
+  private static final int INFO_LEVEL = Level.INFO.intValue();
+  private static final int DEBUG_LEVEL = Level.FINE.intValue();
+  private static final int VERBOSE_LEVEL = Level.FINER.intValue();
+  private static final ThreadLocal<SimpleDateFormat> DATE_FORMAT =
+    new ThreadLocal<SimpleDateFormat>() {
+        @Override
+        protected SimpleDateFormat initialValue() {
+            SimpleDateFormat format = new SimpleDateFormat(
+                "[yyyy-MM-dd HH:mm:ss.SSS]",
+                Locale.US);
+            format.setTimeZone(TimeZone.getDefault());
+            return format;
+        }
+    };
+
+  @Override
+  public String format(LogRecord record) {
+    String timestamp = DATE_FORMAT.get().format(new Date(record.getMillis()));
+
+    // We explicitly don't use String.format here because this code is very
+    // performance-critical: http://stackoverflow.com/a/1281651
+    long tid = record.getThreadID();
+    StringBuilder sb = new StringBuilder(timestamp)
+      .append(formatRecordLevel(record.getLevel()))
+      .append("[tid:");
+    // Zero-pad on the left. We're currently assuming we have less than 100 threads.
+    if (tid < 10) {
+      sb.append("0").append(tid);
+    } else {
+      sb.append(tid);
+    }
+    sb.append("][")
+      .append(record.getLoggerName())
+      .append("] ")
+      .append(formatMessage(record))
+      .append("\n");
+    Throwable t = record.getThrown();
+    if (t != null) {
+      // Closing a StringWriter has no effect, so we don't need to do it in a
+      // try-with-resources (but oddly, it throws IOException, so we couldn't
+      // use it in a try-with-resources if we wanted to).
+      StringWriter sw = new StringWriter();
+      try (PrintWriter pw = new PrintWriter(sw)) {
+        t.printStackTrace(pw);
+        sb.append(sw)
+            .append("\n");
+      }
+    }
+    return sb.toString();
+  }
+
+  private static String formatRecordLevel(Level level) {
+    int l = level.intValue();
+    if (l == ERROR_LEVEL) {
+      return "[error]";
+    } else if (l == WARN_LEVEL) {
+      return "[warn ]";
+    } else if (l == INFO_LEVEL) {
+      return "[info ]";
+    } else if (l == DEBUG_LEVEL) {
+      return "[debug]";
+    } else if (l == VERBOSE_LEVEL) {
+      return "[vrbos]";
+    } else {
+      // We don't expect this to happen, so meh, let's use String.format for simplicity.
+      return String.format("[%-5d]", l);
+    }
+  }
+}

test/com/facebook/buck/junit/LoggingIntegrationTest.java

@@ -0,0 +1,80 @@
+/*
+ * Copyright 2015-present Facebook, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License"); you may
+ * not use this file except in compliance with the License. You may obtain
+ * a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+ * WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+ * License for the specific language governing permissions and limitations
+ * under the License.
+ */
+
+package com.facebook.buck.junit;
+
+import static org.junit.Assert.assertThat;
+
+import static org.hamcrest.Matchers.arrayWithSize;
+import static org.hamcrest.Matchers.not;
+import static org.hamcrest.Matchers.containsString;
+
+import com.facebook.buck.testutil.integration.DebuggableTemporaryFolder;
+import com.facebook.buck.testutil.integration.ProjectWorkspace;
+import com.facebook.buck.testutil.integration.TestDataHelper;
+
+import org.junit.Rule;
+import org.junit.Test;
+
+import java.io.IOException;
+
+public class LoggingIntegrationTest {
+
+  @Rule
+  public DebuggableTemporaryFolder temp = new DebuggableTemporaryFolder();
+
+  @Test
+  public void logOutputIsOnlyReportedForTestWhichFails() throws IOException {
+    ProjectWorkspace workspace = TestDataHelper.createProjectWorkspaceForScenario(
+        this,
+        "test_with_logging",
+        temp);
+    workspace.setUp();
+
+    ProjectWorkspace.ProcessResult result = workspace.runBuckCommand("test", "//:logging");
+    result.assertTestFailure();
+
+    // stdout should get all debug messages and up when a test fails.
+    String testOutput = result.getStderr();
+    String[] testOutputBeforeAndAfterDebugLogs = testOutput.split(
+        JUnitRunner.JUL_DEBUG_LOGS_HEADER);
+    assertThat(testOutputBeforeAndAfterDebugLogs, arrayWithSize(2));
+    String testOutputAfterDebugLogs = testOutputBeforeAndAfterDebugLogs[1];
+    String[] testOutputBeforeAndAfterErrorLogs =
+        testOutputAfterDebugLogs.split(JUnitRunner.JUL_ERROR_LOGS_HEADER);
+    assertThat(testOutputBeforeAndAfterErrorLogs, arrayWithSize(2));
+    String debugLogs = testOutputBeforeAndAfterErrorLogs[0];
+    String errorLogs = testOutputBeforeAndAfterErrorLogs[1];
+
+    // debugLogs should get debug messages and up when a test fails.
+    assertThat(debugLogs, containsString("This is an error in a failing test"));
+    assertThat(debugLogs, containsString("This is a warning in a failing test"));
+    assertThat(debugLogs, containsString("This is an info message in a failing test"));
+    assertThat(debugLogs, containsString("This is a debug message in a failing test"));
+    assertThat(debugLogs, not(containsString("This is a verbose message in a failing test")));
+
+    // errorLogs should get warnings and errors only when a test fails.
+    assertThat(errorLogs, containsString("This is an error in a failing test"));
+    assertThat(errorLogs, containsString("This is a warning in a failing test"));
+    assertThat(errorLogs, not(containsString("This is an info message in a failing test")));
+    assertThat(errorLogs, not(containsString("This is a debug message in a failing test")));
+    assertThat(errorLogs, not(containsString("This is a verbose message in a failing test")));
+
+    // None of the messages printed in the passing test should be in the output.
+    assertThat(debugLogs, not(containsString("in a passing test")));
+    assertThat(errorLogs, not(containsString("in a passing test")));
+  }
+}

test/com/facebook/buck/junit/testdata/test_with_logging/BUCK

@@ -0,0 +1,28 @@
+java_test(
+  name = 'logging',
+  srcs = [
+    'LoggingTest.java',
+  ],
+  deps = [
+    ':junit',
+  ],
+)
+
+prebuilt_jar(
+  name = 'junit',
+  binary_jar = 'junit-4.11.jar',
+  deps = [
+    ':hamcrest-core',
+    ':hamcrest-library',
+  ],
+)
+
+prebuilt_jar(
+  name = 'hamcrest-core',
+  binary_jar = 'hamcrest-core-1.3.jar',
+)
+
+prebuilt_jar(
+  name = 'hamcrest-library',
+  binary_jar = 'hamcrest-library-1.3.jar',
+)