Skip to content

Build: Improve test status logging #28563

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Feb 9, 2018
Merged

Build: Improve test status logging #28563

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
155 changes: 70 additions & 85 deletions buildSrc/src/main/groovy/com/carrotsearch/gradle/junit4/TestProgressLogger.groovy
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -21,9 +21,14 @@ package com.carrotsearch.gradle.junit4

import com.carrotsearch.ant.tasks.junit4.JUnit4
import com.carrotsearch.ant.tasks.junit4.dependencies.com.google.common.eventbus.Subscribe
import com.carrotsearch.ant.tasks.junit4.events.TestStartedEvent
import com.carrotsearch.ant.tasks.junit4.events.aggregated.AggregatedQuitEvent
import com.carrotsearch.ant.tasks.junit4.events.aggregated.AggregatedStartEvent
import com.carrotsearch.ant.tasks.junit4.events.aggregated.AggregatedSuiteResultEvent
import com.carrotsearch.ant.tasks.junit4.events.aggregated.AggregatedSuiteStartedEvent
import com.carrotsearch.ant.tasks.junit4.events.aggregated.AggregatedTestResultEvent
import com.carrotsearch.ant.tasks.junit4.events.aggregated.ChildBootstrap
import com.carrotsearch.ant.tasks.junit4.events.aggregated.HeartBeatEvent
import com.carrotsearch.ant.tasks.junit4.listeners.AggregatedEventListener
import org.gradle.internal.logging.progress.ProgressLogger
import org.gradle.internal.logging.progress.ProgressLoggerFactory
Expand All @@ -34,7 +39,6 @@ import static com.carrotsearch.ant.tasks.junit4.events.aggregated.TestStatus.FAI
import static com.carrotsearch.ant.tasks.junit4.events.aggregated.TestStatus.IGNORED
import static com.carrotsearch.ant.tasks.junit4.events.aggregated.TestStatus.IGNORED_ASSUMPTION
import static com.carrotsearch.ant.tasks.junit4.events.aggregated.TestStatus.OK
import static java.lang.Math.max

/**
* Adapts junit4's event listeners into gradle's ProgressLogger. Note that
Expand All @@ -54,137 +58,118 @@ import static java.lang.Math.max
class TestProgressLogger implements AggregatedEventListener {
/** Factory to build a progress logger when testing starts */
ProgressLoggerFactory factory
ProgressLogger progressLogger
ProgressLogger parentProgressLogger
ProgressLogger suiteLogger
ProgressLogger testLogger
ProgressLogger[] slaveLoggers
int totalSuites
int totalSlaves

// sprintf formats used to align the integers we print
String suitesFormat
String slavesFormat
String testsFormat

// Counters incremented test completion.
volatile int suitesCompleted = 0
volatile int testsCompleted = 0
volatile int testsFailed = 0
volatile int testsIgnored = 0

// Information about the last, most interesting event.
volatile String eventDescription
volatile int eventSlave
volatile long eventExecutionTime

/** Have we finished a whole suite yet? */
volatile boolean suiteFinished = false
/* Note that we probably overuse volatile here but it isn't hurting us and
lets us move things around without worrying about breaking things. */

@Subscribe
void onStart(AggregatedStartEvent e) throws IOException {
totalSuites = e.suiteCount
totalSlaves = e.slaveCount
progressLogger = factory.newOperation(TestProgressLogger)
progressLogger.setDescription('Randomized test runner')
progressLogger.started()
progressLogger.progress(
"Starting JUnit4 for ${totalSuites} suites on ${totalSlaves} jvms")

suitesFormat = "%0${widthForTotal(totalSuites)}d"
slavesFormat = "%-${widthForTotal(totalSlaves)}s"
/* Just guess the number of tests because we can't figure it out from
here and it isn't worth doing anything fancy to prevent the console
from jumping around a little. 200 is a pretty wild guess for the
minimum but it makes REST tests output sanely. */
int totalNumberOfTestsGuess = max(200, totalSuites * 10)
testsFormat = "%0${widthForTotal(totalNumberOfTestsGuess)}d"
parentProgressLogger = factory.newOperation(TestProgressLogger)
parentProgressLogger.setDescription('Randomized test runner')
parentProgressLogger.started()

suiteLogger = factory.newOperation(TestProgressLogger, parentProgressLogger)
suiteLogger.setDescription('Suite logger')
suiteLogger.started("Suites: 0/" + totalSuites)
testLogger = factory.newOperation(TestProgressLogger, parentProgressLogger)
testLogger.setDescription('Test logger')
testLogger.started('Tests: completed: 0, failed: 0, ignored: 0')
slaveLoggers = new ProgressLogger[e.slaveCount]
for (int i = 0; i < e.slaveCount; ++i) {
slaveLoggers[i] = factory.newOperation(TestProgressLogger, parentProgressLogger)
slaveLoggers[i].setDescription("J${i} test logger")
slaveLoggers[i].started("J${i}: initializing...")
}
}

@Subscribe
void onChildBootstrap(ChildBootstrap e) throws IOException {
slaveLoggers[e.getSlave().id].progress("J${e.slave.id}: starting (pid ${e.slave.pidString})")
}

@Subscribe
void onQuit(AggregatedQuitEvent e) throws IOException {
suiteLogger.completed()
testLogger.completed()
for (ProgressLogger slaveLogger : slaveLoggers) {
slaveLogger.completed()
}
parentProgressLogger.completed()
}

@Subscribe
void onSuiteStart(AggregatedSuiteStartedEvent e) throws IOException {
String suiteName = simpleName(e.suiteStartedEvent.description.className)
slaveLoggers[e.slave.id].progress("J${e.slave.id}: ${suiteName} - initializing")
}

@Subscribe
void onSuiteResult(AggregatedSuiteResultEvent e) throws IOException {
suitesCompleted++
suiteLogger.progress("Suites: " + suitesCompleted + "/" + totalSuites)
}

@Subscribe
void onTestResult(AggregatedTestResultEvent e) throws IOException {
final String statusMessage
testsCompleted++
switch (e.status) {
case ERROR:
case FAILURE:
testsFailed++
statusMessage = "failed"
break
case IGNORED:
case IGNORED_ASSUMPTION:
testsIgnored++
statusMessage = "ignored"
break
case OK:
String time = formatDurationInSeconds(e.executionTime)
statusMessage = "completed [${time}]"
break
default:
throw new IllegalArgumentException(
"Unknown test status: [${e.status}]")
throw new IllegalArgumentException("Unknown test status: [${e.status}]")
}
if (!suiteFinished) {
updateEventInfo(e)
}

log()
testLogger.progress("Tests: completed: ${testsCompleted}, failed: ${testsFailed}, ignored: ${testsIgnored}")
String testName = simpleName(e.description.className) + '.' + e.description.methodName
slaveLoggers[e.slave.id].progress("J${e.slave.id}: ${testName} ${statusMessage}")
}

@Subscribe
void onSuiteResult(AggregatedSuiteResultEvent e) throws IOException {
suitesCompleted++
suiteFinished = true
updateEventInfo(e)
log()
void onTestStarted(TestStartedEvent e) throws IOException {
String testName = simpleName(e.description.className) + '.' + e.description.methodName
slaveLoggers[e.slave.id].progress("J${e.slave.id}: ${testName} ...")
}

/**
* Update the suite information with a junit4 event.
*/
private void updateEventInfo(Object e) {
eventDescription = simpleName(e.description.className)
if (e.description.methodName != null) {
eventDescription += "#${e.description.methodName}"
}
eventSlave = e.slave.id
eventExecutionTime = e.executionTime
@Subscribe
void onHeartbeat(HeartBeatEvent e) throws IOException {
String testName = simpleName(e.description.className) + '.' + e.description.methodName
String time = formatDurationInSeconds(e.getNoEventDuration())
slaveLoggers[e.slave.id].progress("J${e.slave.id}: ${testName} stalled for ${time}")
}

/**
* Extract a Class#getSimpleName style name from Class#getName style
* string. We can't just use Class#getSimpleName because junit descriptions
* don't alway s set the class field but they always set the className
* don't always set the class field but they always set the className
* field.
*/
private static String simpleName(String className) {
return className.substring(className.lastIndexOf('.') + 1)
}

private void log() {
/* Remember that instances of this class are only ever active on one
thread at a time so there really aren't race conditions here. It'd be
OK if there were because they'd only display an overcount
temporarily. */
String log = ''
if (totalSuites > 1) {
/* Skip printing the suites to save space when there is only a
single suite. This is nice because when there is only a single
suite we log the method name and those can be long. */
log += sprintf("Suites [${suitesFormat}/${suitesFormat}], ",
[suitesCompleted, totalSuites])
}
log += sprintf("Tests [${testsFormat}|%d|%d], ",
[testsCompleted, testsFailed, testsIgnored])
log += "in ${formatDurationInSeconds(eventExecutionTime)} "
if (totalSlaves > 1) {
/* Skip printing the slaves if there is only one of them. This is
nice because when there is only a single slave there is often
only a single suite and we could use the extra space to log the
test method names. */
log += "J${sprintf(slavesFormat, eventSlave)} "
}
log += "completed ${eventDescription}"
progressLogger.progress(log)
}

private static int widthForTotal(int total) {
return ((total - 1) as String).length()
}

@Override
void setOuter(JUnit4 junit) {}
}