Merge pull request #14850 from rjernst/log_better

Improve test output on errors and when debugging
This commit is contained in:
Ryan Ernst 2015-11-19 10:39:33 -08:00
commit b7d4489176
5 changed files with 81 additions and 39 deletions

View File

@ -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')
junit4.junit4(attributes) {
classpath {
pathElement(path: classpath.asPath)
DefaultLogger listener = null
ByteArrayOutputStream antLoggingBuffer = null
if (logger.isInfoEnabled() == false) {
// 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) {
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)
project.ant.project.addBuildListener(listener)
}
NamespaceBuilderSupport junit4 = NamespaceBuilder.newInstance(ant, 'junit4')
try {
junit4.junit4(attributes) {
classpath {
pathElement(path: classpath.asPath)
}
for (String excludePattern : patternSet.getExcludes()) {
exclude(name: excludePattern)
if (enableAssertions) {
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) {
sysproperty key: prop.getKey(), value: prop.getValue()
} catch (BuildException e) {
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)
}
}

View File

@ -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

View File

@ -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 {

View File

@ -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
/**

View File

@ -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