Improve JUnit test runner output

5 files changed, 86 insertions, 22 deletions

diff --git a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/HtmlLogger.java b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/HtmlLogger.java
index aa1900b8446..321ff11d1bd 100644
--- a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/HtmlLogger.java
+++ b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/HtmlLogger.java
@@ -23,7 +23,7 @@ public class HtmlLogger {
 
     public LogRecord toLog(String line) {
         if (line.length() > 1 << 13)
-            line = line.substring(0, 1 << 13) + " ... (" + (line.length() - (1 << 13)) + " bytes truncated due to size)";
+            line = line.substring(0, 1 << 13) + " ... (" + (line.length() - (1 << 13)) + " more bytes truncated)";
 
         buffer.reset();
         try (PrintStream formatter = new PrintStream(new HtmlAnsiOutputStream(buffer))) {
diff --git a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/JunitRunner.java b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/JunitRunner.java
index 1e1d6eeaa14..1099775c0dd 100644
--- a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/JunitRunner.java
+++ b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/JunitRunner.java
@@ -13,6 +13,7 @@ import com.yahoo.io.IOUtils;
 import com.yahoo.jdisc.application.OsgiFramework;
 import com.yahoo.vespa.defaults.Defaults;
 import org.junit.jupiter.engine.JupiterTestEngine;
+import org.junit.platform.engine.UniqueId;
 import org.junit.platform.engine.discovery.DiscoverySelectors;
 import org.junit.platform.launcher.Launcher;
 import org.junit.platform.launcher.LauncherDiscoveryRequest;
@@ -201,7 +202,9 @@ public class JunitRunner extends AbstractComponent implements TestRunner {
         var failures = report.getFailures().stream()
                 .map(failure -> {
                     TestReport.trimStackTraces(failure.getException(), JunitRunner.class.getName());
-                    return new TestReport.Failure(failure.getTestIdentifier().getUniqueId(), failure.getException());
+                    return new TestReport.Failure(failure.getTestIdentifier().getParentId().map(id -> id + ".").orElse("") +
+                                                  failure.getTestIdentifier().getDisplayName(),
+                                                  failure.getException());
                 })
                 .collect(Collectors.toList());
         long inconclusive = isProductionTest ? failures.stream()
@@ -212,7 +215,7 @@ public class JunitRunner extends AbstractComponent implements TestRunner {
                 .withSuccessCount(report.getTestsSucceededCount())
                 .withAbortedCount(report.getTestsAbortedCount())
                 .withIgnoredCount(report.getTestsSkippedCount())
-                .withFailedCount(report.getTotalFailureCount() - inconclusive)
+                .withFailedCount(report.getTestsFailedCount() - inconclusive)
                 .withInconclusiveCount(inconclusive)
                 .withFailures(failures)
                 .withLogs(logRecords.values())
diff --git a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestRunnerHandler.java b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestRunnerHandler.java
index a4c4023c270..8408a7703be 100644
--- a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestRunnerHandler.java
+++ b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestRunnerHandler.java
@@ -17,6 +17,8 @@ import com.yahoo.yolean.Exceptions;
 import java.io.ByteArrayOutputStream;
 import java.io.IOException;
 import java.io.PrintStream;
+import java.time.ZoneOffset;
+import java.time.format.DateTimeFormatter;
 import java.util.Collection;
 import java.util.Optional;
 import java.util.concurrent.Executor;
@@ -32,6 +34,8 @@ import static com.yahoo.jdisc.Response.Status;
  */
 public class TestRunnerHandler extends ThreadedHttpRequestHandler {
 
+    private static final DateTimeFormatter formatter = DateTimeFormatter.ofPattern("HH:mm:ss.SSS");
+
     private final TestRunner testRunner;
 
     @Inject
@@ -151,7 +155,8 @@ public class TestRunnerHandler extends ThreadedHttpRequestHandler {
         testReport.failures.forEach(failure -> serializeFailure(failure, failureRoot.addObject()));
 
         var output = root.setArray("output");
-        testReport.logLines.forEach(lr -> output.addString(lr.getMessage()));
+        for (LogRecord record : testReport.logLines)
+            output.addString(formatter.format(record.getInstant().atOffset(ZoneOffset.UTC)) + " " + record.getMessage());
 
         return slime;
     }
diff --git a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/VespaJunitLogListener.java b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/VespaJunitLogListener.java
index 8a472452ab2..90a5775f8c2 100644
--- a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/VespaJunitLogListener.java
+++ b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/VespaJunitLogListener.java
@@ -2,25 +2,35 @@
 
 package com.yahoo.vespa.testrunner;
 
+import ai.vespa.hosted.cd.InconclusiveTestException;
 import org.junit.platform.engine.TestExecutionResult;
 import org.junit.platform.engine.reporting.ReportEntry;
 import org.junit.platform.launcher.TestExecutionListener;
 import org.junit.platform.launcher.TestIdentifier;
 
 import java.time.ZoneOffset;
+import java.util.ArrayList;
+import java.util.HashMap;
+import java.util.List;
+import java.util.Map;
+import java.util.NavigableMap;
 import java.util.Set;
+import java.util.concurrent.ConcurrentSkipListMap;
+import java.util.concurrent.CopyOnWriteArrayList;
 import java.util.function.Consumer;
 import java.util.logging.Level;
 import java.util.logging.LogRecord;
-import java.util.stream.Collectors;
 
+import static java.util.Collections.emptyNavigableMap;
 import static java.util.Objects.requireNonNull;
 import static java.util.logging.Level.INFO;
 import static java.util.logging.Level.SEVERE;
 import static java.util.logging.Level.WARNING;
+import static java.util.stream.Collectors.joining;
 
 class VespaJunitLogListener implements TestExecutionListener {
 
+    private final Map<String, NavigableMap<Status, List<String>>> results = new ConcurrentSkipListMap<>();
     private final Consumer<LogRecord> logger;
 
     VespaJunitLogListener(Consumer<LogRecord> logger) {
@@ -38,30 +48,66 @@ class VespaJunitLogListener implements TestExecutionListener {
     @Override
     public void executionStarted(TestIdentifier testIdentifier) {
         if (testIdentifier.isContainer() && testIdentifier.getParentId().isPresent()) // Skip root engine level.
-            log(INFO, "Tests started in: " + testIdentifier.getDisplayName());
+            log(INFO, "Running all tests in: " + testIdentifier.getDisplayName());
         if (testIdentifier.isTest())
-            log(INFO, "Test started: " + testIdentifier.getDisplayName());
+            log(INFO, "Running test: " + testIdentifier.getDisplayName());
     }
 
     @Override
     public void executionSkipped(TestIdentifier testIdentifier, String reason) {
         log(WARNING, "Skipped: " +  testIdentifier.getDisplayName() + ": " +  reason);
+        if (testIdentifier.isTest())
+            testIdentifier.getParentId().ifPresent(parent -> {
+                results.computeIfAbsent(parent, __ -> new ConcurrentSkipListMap<>())
+                       .computeIfAbsent(Status.skipped, __ -> new CopyOnWriteArrayList<>())
+                       .add(testIdentifier.getDisplayName());
+            });
     }
 
     @Override
     public void executionFinished(TestIdentifier testIdentifier, TestExecutionResult testExecutionResult) {
-        Level level;
-        String message;
-        switch (testExecutionResult.getStatus()) {
-            case FAILED:     level = SEVERE;  message = "failed";    break;
-            case ABORTED:    level = WARNING; message = "skipped";   break;
-            case SUCCESSFUL: level = INFO;    message = "succeeded"; break;
-            default:         level = INFO;    message = "completed"; break;
+        if (testIdentifier.isContainer()) {
+            if (testIdentifier.getParentIdObject().isPresent()) {
+                NavigableMap<Status, List<String>> children = results.getOrDefault(testIdentifier.getUniqueId(), emptyNavigableMap());
+                Level level = children.containsKey(Status.failed) ? SEVERE : INFO;
+                log(level,
+                    "Tests in " + testIdentifier.getDisplayName() + " done: " +
+                    children.entrySet().stream().map(entry -> entry.getValue().size() + " " + entry.getKey()).collect(joining(", ")));
+            }
+            else {
+                Map<Status, List<String>> testResults = new HashMap<>();
+                results.forEach((parent, results) -> results.forEach((status, tests) -> tests.forEach(test -> testResults.computeIfAbsent(status, __ -> new ArrayList<>())
+                                                                                                                         .add(parent + "." + test))));
+                log(INFO, "Done running " + testResults.values().stream().mapToInt(List::size).sum() + " tests:");
+                testResults.forEach((status, tests) -> {
+                    if (status != Status.successful)
+                        log(status == Status.failed ? SEVERE : status == Status.inconclusive ? INFO : WARNING,
+                            status.name().substring(0, 1).toUpperCase() + status.name().substring(1) + " tests:\n" + String.join("\n", tests));
+                });
+            }
+        }
+        if (testIdentifier.isTest()) {
+            Level level;
+            Status status;
+            if (testExecutionResult.getThrowable().map(InconclusiveTestException.class::isInstance).orElse(false)) {
+                level = INFO;
+                 status = Status.inconclusive;
+            }
+            else {
+                switch (testExecutionResult.getStatus()) {
+                    case SUCCESSFUL: level = INFO;    status = Status.successful; break;
+                    case ABORTED:    level = WARNING; status = Status.aborted;    break;
+                    case FAILED:
+                    default:         level = SEVERE;  status = Status.failed;     break;
+                }
+            }
+            testIdentifier.getParentId().ifPresent(parent -> {
+                results.computeIfAbsent(parent, __ -> new ConcurrentSkipListMap<>())
+                       .computeIfAbsent(status, __ -> new CopyOnWriteArrayList<>())
+                       .add(testIdentifier.getDisplayName());
+            });
+            log(level, "Test " + status + ": " + testIdentifier.getDisplayName(), testExecutionResult.getThrowable().orElse(null));
         }
-        if (testIdentifier.isContainer() && testIdentifier.getParentId().isPresent()) // Skip root engine level.
-            log(level, "Tests " + message + " in: " + testIdentifier.getDisplayName(), testExecutionResult.getThrowable().orElse(null));
-        if (testIdentifier.isTest())
-            log(level, "Test " + message + ": " + testIdentifier.getDisplayName(), testExecutionResult.getThrowable().orElse(null));
     }
 
     @Override
@@ -70,7 +116,7 @@ class VespaJunitLogListener implements TestExecutionListener {
                 ? report.getKeyValuePairs().get("value")
                 : report.getKeyValuePairs().entrySet().stream()
                         .map(entry -> entry.getKey() + ": " + entry.getValue())
-                        .collect(Collectors.joining("\n"));
+                        .collect(joining("\n"));
         LogRecord record = new LogRecord(INFO, message);
         record.setInstant(report.getTimestamp().toInstant(ZoneOffset.UTC));
         logger.accept(record);
@@ -86,4 +132,14 @@ class VespaJunitLogListener implements TestExecutionListener {
         logger.accept(record);
     }
 
+    private enum Status {
+
+        successful,
+        inconclusive,
+        failed,
+        aborted,
+        skipped;
+
+    }
+
 }
diff --git a/vespa-osgi-testrunner/src/test/java/com/yahoo/vespa/testrunner/TestRunnerHandlerTest.java b/vespa-osgi-testrunner/src/test/java/com/yahoo/vespa/testrunner/TestRunnerHandlerTest.java
index cd120967bf4..49dd2b20797 100644
--- a/vespa-osgi-testrunner/src/test/java/com/yahoo/vespa/testrunner/TestRunnerHandlerTest.java
+++ b/vespa-osgi-testrunner/src/test/java/com/yahoo/vespa/testrunner/TestRunnerHandlerTest.java
@@ -32,7 +32,7 @@ import static org.mockito.Mockito.when;
  */
 class TestRunnerHandlerTest {
 
-    private static final Instant testInstant = Instant.ofEpochMilli(1598432151660L);
+    private static final Instant testInstant = Instant.ofEpochMilli(12_000L);
 
     private TestRunnerHandler testRunnerHandler;
     private TestRunner aggregateRunner;
@@ -60,7 +60,7 @@ class TestRunnerHandlerTest {
         HttpResponse response = testRunnerHandler.handle(HttpRequest.createTestRequest("http://localhost:1234/tester/v1/report", GET));
         ByteArrayOutputStream out = new ByteArrayOutputStream();
         response.render(out);
-        JsonTestHelper.assertJsonEquals(out.toString(UTF_8), "{\"summary\":{\"success\":1,\"failed\":2,\"ignored\":3,\"aborted\":4,\"inconclusive\":5,\"failures\":[{\"testName\":\"Foo.bar()\",\"testError\":\"org.junit.ComparisonFailure: expected:<foo> but was:<bar>\",\"exception\":\"java.lang.RuntimeException: org.junit.ComparisonFailure: expected:<foo> but was:<bar>\\n\\tat Foo.bar(Foo.java:1123)\\n\"}]},\"output\":[\"Tests started\"]}");
+        JsonTestHelper.assertJsonEquals(out.toString(UTF_8), "{\"summary\":{\"success\":1,\"failed\":2,\"ignored\":3,\"aborted\":4,\"inconclusive\":5,\"failures\":[{\"testName\":\"Foo.bar()\",\"testError\":\"org.junit.ComparisonFailure: expected:<foo> but was:<bar>\",\"exception\":\"java.lang.RuntimeException: org.junit.ComparisonFailure: expected:<foo> but was:<bar>\\n\\tat Foo.bar(Foo.java:1123)\\n\"}]},\"output\":[\"00:00:12.000 Tests started\"]}");
     }
 
     @Test
@@ -71,7 +71,7 @@ class TestRunnerHandlerTest {
         HttpResponse response = testRunnerHandler.handle(HttpRequest.createTestRequest("http://localhost:1234/tester/v1/log", GET));
         ByteArrayOutputStream out = new ByteArrayOutputStream();
         response.render(out);
-        JsonTestHelper.assertJsonEquals(out.toString(UTF_8), "{\"logRecords\":[{\"id\":0,\"at\":1598432151660,\"type\":\"info\",\"message\":\"Tests started\"}]}");
+        JsonTestHelper.assertJsonEquals(out.toString(UTF_8), "{\"logRecords\":[{\"id\":0,\"at\":12000,\"type\":\"info\",\"message\":\"Tests started\"}]}");
 
         // Should not get old log
         response = testRunnerHandler.handle(HttpRequest.createTestRequest("http://localhost:1234/tester/v1/log?after=0", GET));