Test report failures as log records

4 files changed, 172 insertions, 41 deletions

diff --git a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestReport.java b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestReport.java
index 9aae329d7fb..6c26f0e67a4 100644
--- a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestReport.java
+++ b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestReport.java
@@ -20,6 +20,7 @@ import java.util.List;
 import java.util.Map;
 import java.util.Queue;
 import java.util.Set;
+import java.util.logging.Level;
 import java.util.logging.LogRecord;
 
 import static java.util.Arrays.copyOf;
@@ -52,7 +53,7 @@ public class TestReport {
         if (thrown instanceof OutOfMemoryError) throw (Error) thrown;
         TestReport failed = new TestReport(clock, suite);
         failed.complete();
-        failed.root().children.add(new FailureNode(failed.root(), thrown, suite));
+        failed.root().children.add(new FailureNode(failed.root(), clock.instant(), thrown, suite));
         return failed;
     }
 
@@ -126,7 +127,7 @@ public class TestReport {
         synchronized (monitor) {
             Status status = Status.successful;
             if (thrown != null) {
-                FailureNode failure = new FailureNode(current, thrown, suite);
+                FailureNode failure = new FailureNode(current, clock.instant(), thrown, suite);
                 current.children.add(failure);
                 status = failure.status();
             }
@@ -271,22 +272,35 @@ public class TestReport {
 
     }
 
-    public static class FailureNode extends Node {
+    public static class FailureNode extends NamedNode {
 
         private final Throwable thrown;
         private final Suite suite;
 
-        public FailureNode(NamedNode parent, Throwable thrown, Suite suite) {
-            super(parent);
-            this.thrown = thrown;
+        public FailureNode(NamedNode parent, Instant now, Throwable thrown, Suite suite) {
+            super(parent, null, thrown.toString(), now);
             trimStackTraces(thrown, JunitRunner.class.getName());
+            this.thrown = thrown;
             this.suite = suite;
+
+            LogRecord record = new LogRecord(levelOf(status()), null);
+            record.setThrown(thrown);
+            record.setInstant(now);
+            OutputNode child = new OutputNode(this);
+            child.log.add(record);
+            children.add(child);
         }
 
         public Throwable thrown() {
             return thrown;
         }
 
+        @Override
+        public Duration duration() {
+            return Duration.ZERO;
+        }
+
+        @Override
         public Status status() {
             return suite == Suite.PRODUCTION_TEST && thrown instanceof InconclusiveTestException
                    ? Status.inconclusive
@@ -307,6 +321,10 @@ public class TestReport {
 
     }
 
+    static Level levelOf(Status status) {
+        return status.compareTo(Status.failed) >= 0 ? Level.SEVERE : status.compareTo(Status.skipped) >= 0 ? Level.WARNING : Level.INFO;
+    }
+
     /**
      * Recursively trims stack traces for the given throwable and its causes/suppressed.
      * This is based on the assumption that the relevant stack is anything above the first native
diff --git a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestReportGeneratingListener.java b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestReportGeneratingListener.java
index 0d767f5aa8a..5bc9fda6835 100644
--- a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestReportGeneratingListener.java
+++ b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestReportGeneratingListener.java
@@ -110,7 +110,7 @@ class TestReportGeneratingListener implements TestExecutionListener {
                     ? report.abort(testIdentifier)
                     : report.complete(testIdentifier, testExecutionResult.getThrowable().orElse(null));
         Status status = node.status();
-        Level level = status.compareTo(Status.failed) >= 0 ? SEVERE : status.compareTo(Status.skipped) >= 0 ? WARNING : INFO;
+        Level level = TestReport.levelOf(status);
 
         if (testIdentifier.isContainer()) {
             if (testIdentifier.getParentIdObject().isPresent()) {
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 b1ca6c84b75..19d7afc0a81 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
@@ -14,6 +14,7 @@ import com.yahoo.slime.Cursor;
 import com.yahoo.slime.Slime;
 import com.yahoo.vespa.testrunner.TestReport.ContainerNode;
 import com.yahoo.vespa.testrunner.TestReport.FailureNode;
+import com.yahoo.vespa.testrunner.TestReport.NamedNode;
 import com.yahoo.vespa.testrunner.TestReport.Node;
 import com.yahoo.vespa.testrunner.TestReport.OutputNode;
 import com.yahoo.vespa.testrunner.TestReport.TestNode;
@@ -176,14 +177,13 @@ public class TestRunnerHandler extends ThreadedHttpRequestHandler {
         }
         if (node instanceof OutputNode)
             for (LogRecord record : ((OutputNode) node).log())
-                outputArray.addString(formatter.format(record.getInstant().atOffset(ZoneOffset.UTC)) + " " + record.getMessage());
+                if (record.getMessage() != null)
+                    outputArray.addString(formatter.format(record.getInstant().atOffset(ZoneOffset.UTC)) + " " + record.getMessage());
     }
 
     static void toSlime(Cursor nodeObject, Node node) {
-        if (node instanceof ContainerNode) toSlime(nodeObject, (ContainerNode) node);
-        if (node instanceof TestNode) toSlime(nodeObject, (TestNode) node);
+        if (node instanceof NamedNode) toSlime(nodeObject, (NamedNode) node);
         if (node instanceof OutputNode) toSlime(nodeObject, (OutputNode) node);
-        if (node instanceof FailureNode) toSlime(nodeObject, (FailureNode) node);
 
         if ( ! node.children().isEmpty()) {
             Cursor childrenArray = nodeObject.setArray("children");
@@ -192,16 +192,9 @@ public class TestRunnerHandler extends ThreadedHttpRequestHandler {
         }
     }
 
-    static void toSlime(Cursor nodeObject, ContainerNode node) {
-        nodeObject.setString("type", "container");
-        nodeObject.setString("name", node.name());
-        nodeObject.setString("status", node.status().name());
-        nodeObject.setLong("start", node.start().toEpochMilli());
-        nodeObject.setLong("duration", node.duration().toMillis());
-    }
-
-    static void toSlime(Cursor nodeObject, TestNode node) {
-        nodeObject.setString("type", "test");
+    static void toSlime(Cursor nodeObject, NamedNode node) {
+        String type = node instanceof FailureNode ? "failure" : node instanceof TestNode ? "test" : "container";
+        nodeObject.setString("type", type);
         nodeObject.setString("name", node.name());
         nodeObject.setString("status", node.status().name());
         nodeObject.setLong("start", node.start().toEpochMilli());
@@ -213,19 +206,14 @@ public class TestRunnerHandler extends ThreadedHttpRequestHandler {
         Cursor childrenArray = nodeObject.setArray("children");
         for (LogRecord record : node.log()) {
             Cursor recordObject = childrenArray.addObject();
-            recordObject.setString("message", (record.getLoggerName() == null ? "" : record.getLoggerName() + ": ") + record.getMessage());
+            recordObject.setString("message", (record.getLoggerName() == null ? "" : record.getLoggerName() + ": ") +
+                                              (record.getMessage() != null ? record.getMessage() : "") +
+                                              (record.getThrown() != null ? (record.getMessage() != null ? "\n" : "") + traceToString(record.getThrown()) : ""));
             recordObject.setLong("at", record.getInstant().toEpochMilli());
             recordObject.setString("level", typeOf(record.getLevel()));
-            if (record.getThrown() != null) recordObject.setString("trace", traceToString(record.getThrown()));
         }
     }
 
-    static void toSlime(Cursor nodeObject, FailureNode node) {
-        nodeObject.setString("type", "failure");
-        nodeObject.setString("status", node.status().name());
-        nodeObject.setString("trace", traceToString(node.thrown()));
-    }
-
     private static String traceToString(Throwable thrown) {
         ByteArrayOutputStream buffer = new ByteArrayOutputStream();
         thrown.printStackTrace(new PrintStream(buffer));
diff --git a/vespa-osgi-testrunner/src/test/resources/report.json b/vespa-osgi-testrunner/src/test/resources/report.json
index 9c41a83a6b5..fa76c222f93 100644
--- a/vespa-osgi-testrunner/src/test/resources/report.json
+++ b/vespa-osgi-testrunner/src/test/resources/report.json
@@ -58,8 +58,22 @@
                   },
                   {
                     "type": "failure",
+                    "name": "java.lang.NoClassDefFoundError",
                     "status": "error",
-                    "trace": "java.lang.NoClassDefFoundError\n\tat com.yahoo.vespa.test.samples.SampleTest.error(SampleTest.java:87)\n"
+                    "start": 0,
+                    "duration": 0,
+                    "children": [
+                      {
+                        "type": "output",
+                        "children": [
+                          {
+                            "message": "java.lang.NoClassDefFoundError\n\tat com.yahoo.vespa.test.samples.SampleTest.error(SampleTest.java:87)\n",
+                            "at": 0,
+                            "level": "error"
+                          }
+                        ]
+                      }
+                    ]
                   }
                 ]
               },
@@ -87,8 +101,22 @@
                   },
                   {
                     "type": "failure",
+                    "name": "org.opentest4j.AssertionFailedError: baz ==> expected: <foo> but was: <bar>",
                     "status": "failed",
-                    "trace": "org.opentest4j.AssertionFailedError: baz ==> expected: <foo> but was: <bar>\n\tat org.junit.jupiter.api.AssertionUtils.fail(AssertionUtils.java:55)\n\tat org.junit.jupiter.api.AssertionUtils.failNotEqual(AssertionUtils.java:62)\n\tat org.junit.jupiter.api.AssertEquals.assertEquals(AssertEquals.java:182)\n\tat org.junit.jupiter.api.Assertions.assertEquals(Assertions.java:1152)\n\tat com.yahoo.vespa.test.samples.SampleTest.failing(SampleTest.java:81)\n"
+                    "start": 0,
+                    "duration": 0,
+                    "children": [
+                      {
+                        "type": "output",
+                        "children": [
+                          {
+                            "message": "org.opentest4j.AssertionFailedError: baz ==> expected: <foo> but was: <bar>\n\tat org.junit.jupiter.api.AssertionUtils.fail(AssertionUtils.java:55)\n\tat org.junit.jupiter.api.AssertionUtils.failNotEqual(AssertionUtils.java:62)\n\tat org.junit.jupiter.api.AssertEquals.assertEquals(AssertEquals.java:182)\n\tat org.junit.jupiter.api.Assertions.assertEquals(Assertions.java:1152)\n\tat com.yahoo.vespa.test.samples.SampleTest.failing(SampleTest.java:81)\n",
+                            "at": 0,
+                            "level": "error"
+                          }
+                        ]
+                      }
+                    ]
                   }
                 ]
               },
@@ -123,8 +151,22 @@
                   },
                   {
                     "type": "failure",
+                    "name": "ai.vespa.hosted.cd.InconclusiveTestException: the cat is both dead _and_ alive",
                     "status": "inconclusive",
-                    "trace": "ai.vespa.hosted.cd.InconclusiveTestException: the cat is both dead _and_ alive\n\tat com.yahoo.vespa.test.samples.SampleTest.inconclusive(SampleTest.java:93)\n"
+                    "start": 0,
+                    "duration": 0,
+                    "children": [
+                      {
+                        "type": "output",
+                        "children": [
+                          {
+                            "message": "ai.vespa.hosted.cd.InconclusiveTestException: the cat is both dead _and_ alive\n\tat com.yahoo.vespa.test.samples.SampleTest.inconclusive(SampleTest.java:93)\n",
+                            "at": 0,
+                            "level": "warning"
+                          }
+                        ]
+                      }
+                    ]
                   }
                 ]
               },
@@ -154,10 +196,9 @@
                         "level": "info"
                       },
                       {
-                        "message": "com.yahoo.vespa.test.samples.SampleTest: Oh no",
+                        "message": "com.yahoo.vespa.test.samples.SampleTest: Oh no\njava.lang.IllegalArgumentException: error\n\tat com.yahoo.vespa.test.samples.SampleTest.successful(SampleTest.java:75)\nCaused by: java.lang.RuntimeException: wrapped\n\t... 1 more\n",
                         "at": 0,
-                        "level": "warning",
-                        "trace": "java.lang.IllegalArgumentException: error\n\tat com.yahoo.vespa.test.samples.SampleTest.successful(SampleTest.java:75)\nCaused by: java.lang.RuntimeException: wrapped\n\t... 1 more\n"
+                        "level": "warning"
                       }
                     ]
                   }
@@ -215,8 +256,22 @@
                         "children": [
                           {
                             "type": "failure",
+                            "name": "org.opentest4j.AssertionFailedError: no charm",
                             "status": "failed",
-                            "trace": "org.opentest4j.AssertionFailedError: no charm\n\tat org.junit.jupiter.api.AssertionUtils.fail(AssertionUtils.java:39)\n\tat org.junit.jupiter.api.Assertions.fail(Assertions.java:134)\n\tat com.yahoo.vespa.test.samples.SampleTest$Inner.lambda$others$1(SampleTest.java:105)\n"
+                            "start": 0,
+                            "duration": 0,
+                            "children": [
+                              {
+                                "type": "output",
+                                "children": [
+                                  {
+                                    "message": "org.opentest4j.AssertionFailedError: no charm\n\tat org.junit.jupiter.api.AssertionUtils.fail(AssertionUtils.java:39)\n\tat org.junit.jupiter.api.Assertions.fail(Assertions.java:134)\n\tat com.yahoo.vespa.test.samples.SampleTest$Inner.lambda$others$1(SampleTest.java:105)\n",
+                                    "at": 0,
+                                    "level": "error"
+                                  }
+                                ]
+                              }
+                            ]
                           }
                         ]
                       }
@@ -286,15 +341,43 @@
                 "children": [
                   {
                     "type": "failure",
+                    "name": "org.opentest4j.AssertionFailedError",
                     "status": "failed",
-                    "trace": "org.opentest4j.AssertionFailedError\n\tat org.junit.jupiter.api.AssertionUtils.fail(AssertionUtils.java:35)\n\tat org.junit.jupiter.api.Assertions.fail(Assertions.java:115)\n\tat com.yahoo.vespa.test.samples.FailingTestAndBothAftersTest.test(FailingTestAndBothAftersTest.java:19)\n\tSuppressed: java.lang.RuntimeException\n\t\tat com.yahoo.vespa.test.samples.FailingTestAndBothAftersTest.moreFail(FailingTestAndBothAftersTest.java:16)\n"
+                    "start": 0,
+                    "duration": 0,
+                    "children": [
+                      {
+                        "type": "output",
+                        "children": [
+                          {
+                            "message": "org.opentest4j.AssertionFailedError\n\tat org.junit.jupiter.api.AssertionUtils.fail(AssertionUtils.java:35)\n\tat org.junit.jupiter.api.Assertions.fail(Assertions.java:115)\n\tat com.yahoo.vespa.test.samples.FailingTestAndBothAftersTest.test(FailingTestAndBothAftersTest.java:19)\n\tSuppressed: java.lang.RuntimeException\n\t\tat com.yahoo.vespa.test.samples.FailingTestAndBothAftersTest.moreFail(FailingTestAndBothAftersTest.java:16)\n",
+                            "at": 0,
+                            "level": "error"
+                          }
+                        ]
+                      }
+                    ]
                   }
                 ]
               },
               {
                 "type": "failure",
+                "name": "java.lang.RuntimeException",
                 "status": "error",
-                "trace": "java.lang.RuntimeException\n\tat com.yahoo.vespa.test.samples.FailingTestAndBothAftersTest.fail(FailingTestAndBothAftersTest.java:13)\n"
+                "start": 0,
+                "duration": 0,
+                "children": [
+                  {
+                    "type": "output",
+                    "children": [
+                      {
+                        "message": "java.lang.RuntimeException\n\tat com.yahoo.vespa.test.samples.FailingTestAndBothAftersTest.fail(FailingTestAndBothAftersTest.java:13)\n",
+                        "at": 0,
+                        "level": "error"
+                      }
+                    ]
+                  }
+                ]
               }
             ]
           },
@@ -307,8 +390,22 @@
             "children": [
               {
                 "type": "failure",
+                "name": "org.junit.platform.commons.JUnitException: @BeforeAll method 'void com.yahoo.vespa.test.samples.WrongBeforeAllTest.wrong()' must be static unless the test class is annotated with @TestInstance(Lifecycle.PER_CLASS).",
                 "status": "error",
-                "trace": "org.junit.platform.commons.JUnitException: @BeforeAll method 'void com.yahoo.vespa.test.samples.WrongBeforeAllTest.wrong()' must be static unless the test class is annotated with @TestInstance(Lifecycle.PER_CLASS).\n"
+                "start": 0,
+                "duration": 0,
+                "children": [
+                  {
+                    "type": "output",
+                    "children": [
+                      {
+                        "message": "org.junit.platform.commons.JUnitException: @BeforeAll method 'void com.yahoo.vespa.test.samples.WrongBeforeAllTest.wrong()' must be static unless the test class is annotated with @TestInstance(Lifecycle.PER_CLASS).\n",
+                        "at": 0,
+                        "level": "error"
+                      }
+                    ]
+                  }
+                ]
               },
               {
                 "type": "test",
@@ -342,8 +439,22 @@
                 "children": [
                   {
                     "type": "failure",
+                    "name": "java.lang.NullPointerException",
                     "status": "error",
-                    "trace": "java.lang.NullPointerException\n\tat com.yahoo.vespa.test.samples.FailingExtensionTest$FailingExtension.<init>(FailingExtensionTest.java:19)\n"
+                    "start": 0,
+                    "duration": 0,
+                    "children": [
+                      {
+                        "type": "output",
+                        "children": [
+                          {
+                            "message": "java.lang.NullPointerException\n\tat com.yahoo.vespa.test.samples.FailingExtensionTest$FailingExtension.<init>(FailingExtensionTest.java:19)\n",
+                            "at": 0,
+                            "level": "error"
+                          }
+                        ]
+                      }
+                    ]
                   }
                 ]
               }
@@ -353,8 +464,22 @@
       },
       {
         "type": "failure",
+        "name": "java.lang.ClassNotFoundException: School's out all summer!",
         "status": "error",
-        "trace": "java.lang.ClassNotFoundException: School's out all summer!\n"
+        "start": 12000,
+        "duration": 0,
+        "children": [
+          {
+            "type": "output",
+            "children": [
+              {
+                "message": "java.lang.ClassNotFoundException: School's out all summer!\n",
+                "at": 12000,
+                "level": "error"
+              }
+            ]
+          }
+        ]
       }
     ]
   },