Build: Improve test output on errors and when debugging

There were a number of subtle issues with the existing logging that
wraps events from Junit4 and ant. This change:
* Tweaks at what level certain events are logged
* Fixes -Dtests.output=always to force everything to be logged
* Makes -Dtests.class imply -Dtests.output=always
* Captures ant logging from junit4, so that direct jvm output will be
  logged on failure when not using gradle info logging

buildSrc/src/main/groovy/com/carrotsearch/gradle/junit4/RandomizedTestingTask.groovy

@@ -3,6 +3,9 @@ package com.carrotsearch.gradle.junit4
 import com.carrotsearch.ant.tasks.junit4.ListenersList
 import com.carrotsearch.ant.tasks.junit4.listeners.AggregatedEventListener
 import groovy.xml.NamespaceBuilder
+import groovy.xml.NamespaceBuilderSupport
+import org.apache.tools.ant.BuildException
+import org.apache.tools.ant.DefaultLogger
 import org.apache.tools.ant.RuntimeConfigurable
 import org.apache.tools.ant.UnknownElement
 import org.gradle.api.DefaultTask
@@ -180,39 +183,78 @@ class RandomizedTestingTask extends DefaultTask {
             heartbeat: testLoggingConfig.slowTests.heartbeat,
             dir: workingDir,
             tempdir: new File(workingDir, 'temp'),
-            haltOnFailure: haltOnFailure,
+            haltOnFailure: true, // we want to capture when a build failed, but will decide whether to rethrow later
             shuffleOnSlave: shuffleOnSlave
         ]
 
-        def junit4 = NamespaceBuilder.newInstance(ant, 'junit4')
+        DefaultLogger listener = null
-        junit4.junit4(attributes) {
+        ByteArrayOutputStream antLoggingBuffer = null
-            classpath {
+        if (logger.isInfoEnabled() == false) {
-                pathElement(path: classpath.asPath)
+            // in info logging, ant already outputs info level, so we see everything
+            // but on errors or when debugging, we want to see info level messages
+            // because junit4 emits jvm output with ant logging
+            if (testLoggingConfig.outputMode == TestLoggingConfiguration.OutputMode.ALWAYS) {
+                // we want all output, so just stream directly
+                listener = new DefaultLogger(
+                        errorPrintStream: System.err,
+                        outputPrintStream: System.out,
+                        messageOutputLevel: org.apache.tools.ant.Project.MSG_INFO)
+            } else {
+                // we want to buffer the info, and emit it if the test fails
+                antLoggingBuffer = new ByteArrayOutputStream()
+                PrintStream stream = new PrintStream(antLoggingBuffer, true, "UTF-8")
+                listener = new DefaultLogger(
+                        errorPrintStream: stream,
+                        outputPrintStream: stream,
+                        messageOutputLevel: org.apache.tools.ant.Project.MSG_INFO)
             }
-            if (enableAssertions) {
+            project.ant.project.addBuildListener(listener)
-                jvmarg(value: '-ea')
+        }
-            }
+
-            if (enableSystemAssertions) {
+        NamespaceBuilderSupport junit4 = NamespaceBuilder.newInstance(ant, 'junit4')
-                jvmarg(value: '-esa')
+        try {
-            }
+            junit4.junit4(attributes) {
-            for (String arg : jvmArgs) {
+                classpath {
-                jvmarg(value: arg)
+                    pathElement(path: classpath.asPath)
-            }
-            if (argLine != null) {
-                jvmarg(line: argLine)
-            }
-            fileset(dir: testClassesDir) {
-                for (String includePattern : patternSet.getIncludes()) {
-                    include(name: includePattern)
                 }
-                for (String excludePattern : patternSet.getExcludes()) {
+                if (enableAssertions) {
-                    exclude(name: excludePattern)
+                    jvmarg(value: '-ea')
                 }
+                if (enableSystemAssertions) {
+                    jvmarg(value: '-esa')
+                }
+                for (String arg : jvmArgs) {
+                    jvmarg(value: arg)
+                }
+                if (argLine != null) {
+                    jvmarg(line: argLine)
+                }
+                fileset(dir: testClassesDir) {
+                    for (String includePattern : patternSet.getIncludes()) {
+                        include(name: includePattern)
+                    }
+                    for (String excludePattern : patternSet.getExcludes()) {
+                        exclude(name: excludePattern)
+                    }
+                }
+                for (Map.Entry<String, String> prop : systemProperties) {
+                    sysproperty key: prop.getKey(), value: prop.getValue()
+                }
+                makeListeners()
             }
-            for (Map.Entry<String, String> prop : systemProperties) {
+        } catch (BuildException e) {
-                sysproperty key: prop.getKey(), value: prop.getValue()
+            if (antLoggingBuffer != null) {
+                logger.error('JUnit4 test failed, ant output was:')
+                logger.error(antLoggingBuffer.toString('UTF-8'))
             }
-            makeListeners()
+            if (haltOnFailure) {
+                throw e;
+            }
+        }
+
+        if (listener != null) {
+            // remove the listener we added so other ant tasks dont have verbose logging!
+            project.ant.project.removeBuildListener(listener)
         }
     }
 

buildSrc/src/main/groovy/com/carrotsearch/gradle/junit4/TestReportLogger.groovy

@@ -79,7 +79,7 @@ class TestReportLogger extends TestsSummaryEventListener implements AggregatedEv
         forkedJvmCount = e.getSlaveCount();
         jvmIdFormat = " J%-" + (1 + (int) Math.floor(Math.log10(forkedJvmCount))) + "d";
 
-        outStream = new LoggingOutputStream(logger: logger, level: LogLevel.ERROR, prefix: "  1> ")
+        outStream = new LoggingOutputStream(logger: logger, level: LogLevel.LIFECYCLE, prefix: "  1> ")
         errStream = new LoggingOutputStream(logger: logger, level: LogLevel.ERROR, prefix: "  2> ")
 
         for (String contains : config.stackTraceFilters.contains) {
@@ -152,13 +152,13 @@ class TestReportLogger extends TestsSummaryEventListener implements AggregatedEv
     void onSuiteStart(AggregatedSuiteStartedEvent e) throws IOException {
         if (isPassthrough()) {
             SuiteStartedEvent evt = e.getSuiteStartedEvent();
-            emitSuiteStart(LogLevel.INFO, evt.getDescription());
+            emitSuiteStart(LogLevel.LIFECYCLE, evt.getDescription());
         }
     }
 
     @Subscribe
     void onOutput(PartialOutputEvent e) throws IOException {
-        if (isPassthrough() && logger.isInfoEnabled()) {
+        if (isPassthrough()) {
             // We only allow passthrough output if there is one JVM.
             switch (e.getEvent().getType()) {
                 case EventType.APPEND_STDERR:
@@ -187,7 +187,6 @@ class TestReportLogger extends TestsSummaryEventListener implements AggregatedEv
 
     @Subscribe
     void onSuiteResult(AggregatedSuiteResultEvent e) throws IOException {
-        try {
         final int completed = suitesCompleted.incrementAndGet();
 
         if (e.isSuccessful() && e.getTests().isEmpty()) {
@@ -197,7 +196,8 @@ class TestReportLogger extends TestsSummaryEventListener implements AggregatedEv
             suiteTimes.put(e.getDescription().getDisplayName(), e.getExecutionTime())
         }
 
-        LogLevel level = e.isSuccessful() ? LogLevel.INFO : LogLevel.ERROR
+        LogLevel level = e.isSuccessful() && config.outputMode != OutputMode.ALWAYS ? LogLevel.INFO : LogLevel.LIFECYCLE
+
         // We must emit buffered test and stream events (in case of failures).
         if (!isPassthrough()) {
             emitSuiteStart(level, e.getDescription())
@@ -214,9 +214,6 @@ class TestReportLogger extends TestsSummaryEventListener implements AggregatedEv
         }
 
         emitSuiteEnd(level, e, completed)
-    } catch (Exception exc) {
-            logger.lifecycle('EXCEPTION: ', exc)
-        }
     }
 
     /** Suite prologue. */
@@ -348,9 +345,9 @@ class TestReportLogger extends TestsSummaryEventListener implements AggregatedEv
         errStream.flush()
     }
 
-    /** Returns true if output should be logged immediately. Only relevant when running with INFO log level. */
+    /** Returns true if output should be logged immediately. */
     boolean isPassthrough() {
-        return forkedJvmCount == 1 && config.outputMode == OutputMode.ALWAYS && logger.isInfoEnabled()
+        return forkedJvmCount == 1 && config.outputMode == OutputMode.ALWAYS
     }
 
     @Override

buildSrc/src/main/groovy/org/elasticsearch/gradle/BuildPlugin.groovy

@@ -307,7 +307,12 @@ class BuildPlugin implements Plugin<Project> {
                     regex(/^(\s+at )(org\.apache\.lucene\.util\.TestRule)/)
                     regex(/^(\s+at )(org\.apache\.lucene\.util\.AbstractBeforeAfterRule)/)
                 }
-                outputMode System.getProperty('tests.output', 'onerror')
+                if (System.getProperty('tests.class') != null && System.getProperty('tests.output') == null) {
+                    // if you are debugging, you want to see the output!
+                    outputMode 'always'
+                } else {
+                    outputMode System.getProperty('tests.output', 'onerror')
+                }
             }
 
             balancers {

buildSrc/src/main/groovy/org/elasticsearch/gradle/vagrant/TapLoggerOutputStream.groovy

@@ -20,10 +20,9 @@ package org.elasticsearch.gradle.vagrant
 
 import com.carrotsearch.gradle.junit4.LoggingOutputStream
 import org.gradle.api.GradleScriptException
-import org.gradle.api.InvalidUserDataException
 import org.gradle.api.logging.Logger
 import org.gradle.logging.ProgressLogger
-import org.gradle.logging.ProgressLoggerFactory
+
 import java.util.regex.Matcher
 
 /**

buildSrc/src/main/groovy/org/elasticsearch/gradle/vagrant/VagrantLoggerOutputStream.groovy

@@ -20,7 +20,6 @@ package org.elasticsearch.gradle.vagrant
 
 import com.carrotsearch.gradle.junit4.LoggingOutputStream
 import org.gradle.logging.ProgressLogger
-import org.gradle.logging.ProgressLoggerFactory
 
 /**
  * Adapts an OutputStream being written to by vagrant into a ProcessLogger. It