From bba7e4ab171fa1f8f5b1cf437d7217f8282c0fcd Mon Sep 17 00:00:00 2001 From: Ryan Ernst Date: Thu, 8 Feb 2018 00:11:02 -0800 Subject: [PATCH] Build: Improve test status logging Tests use the (internal) gradle progress logger. Since aroudn gradle 4.0, loggers can have children loggers which each get their own line of updating output. This commit improves the test status output to give each jvm its own status line, as well as lines for suite and test counts. It also fixes an issue where the progress logger was not marked as completed, which caused its last output to never be cleared. --- .../gradle/junit4/TestProgressLogger.groovy | 155 ++++++++---------- 1 file changed, 70 insertions(+), 85 deletions(-) diff --git a/buildSrc/src/main/groovy/com/carrotsearch/gradle/junit4/TestProgressLogger.groovy b/buildSrc/src/main/groovy/com/carrotsearch/gradle/junit4/TestProgressLogger.groovy index da25afa938916..3b97cfb5f4881 100644 --- a/buildSrc/src/main/groovy/com/carrotsearch/gradle/junit4/TestProgressLogger.groovy +++ b/buildSrc/src/main/groovy/com/carrotsearch/gradle/junit4/TestProgressLogger.groovy @@ -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 @@ -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 @@ -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) {} }