Build: Improve test status logging (#28563)

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.

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) {}
 }