Merge pull request #6605 from vespa-engine/jvenstad/testrunner-logging

Jvenstad/testrunner logging

10 files changed, 186 insertions, 19 deletions

diff --git a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/InternalStepRunner.java b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/InternalStepRunner.java
index 2812ee0d4dd..f0258e2321d 100644
--- a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/InternalStepRunner.java
+++ b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/InternalStepRunner.java
@@ -25,7 +25,6 @@ import com.yahoo.vespa.hosted.controller.api.integration.zone.ZoneId;
 import com.yahoo.vespa.hosted.controller.application.ApplicationPackage;
 import com.yahoo.vespa.hosted.controller.application.ApplicationVersion;
 import com.yahoo.vespa.hosted.controller.application.DeploymentJobs;
-import com.yahoo.vespa.hosted.controller.deployment.Step.Status;
 
 import java.io.ByteArrayOutputStream;
 import java.io.IOException;
@@ -57,9 +56,6 @@ import static com.yahoo.vespa.hosted.controller.deployment.RunStatus.error;
 import static com.yahoo.vespa.hosted.controller.deployment.RunStatus.installationFailed;
 import static com.yahoo.vespa.hosted.controller.deployment.RunStatus.running;
 import static com.yahoo.vespa.hosted.controller.deployment.RunStatus.testFailure;
-import static com.yahoo.vespa.hosted.controller.deployment.Step.Status.failed;
-import static com.yahoo.vespa.hosted.controller.deployment.Step.Status.succeeded;
-import static com.yahoo.vespa.hosted.controller.deployment.Step.Status.unfinished;
 import static java.util.logging.Level.INFO;
 import static java.util.logging.Level.WARNING;
 
@@ -333,7 +329,6 @@ public class InternalStepRunner implements StepRunner {
             case NOT_STARTED:
                 throw new IllegalStateException("Tester reports tests not started, even though they should have!");
             case RUNNING:
-                logger.log("Tests still running ...");
                 return Optional.empty();
             case FAILURE:
                 logger.log("Tests failed.");
@@ -508,7 +503,7 @@ public class InternalStepRunner implements StepRunner {
         }
 
         static ByteArrayLogger of(ApplicationId id, JobType type, Step step) {
-            return new ByteArrayLogger(parent, String.format(".%s.%s.%s", id.serializedForm(), type.jobName(), step));
+            return new ByteArrayLogger(parent, String.format(".%s.%s.%s", id.toString(), type.jobName(), step));
         }
 
         @Override
diff --git a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/Run.java b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/Run.java
index 0d7977c6a9d..70670430bf4 100644
--- a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/Run.java
+++ b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/Run.java
@@ -6,7 +6,6 @@ import com.yahoo.vespa.hosted.controller.api.integration.deployment.RunId;
 import java.time.Instant;
 import java.util.Collections;
 import java.util.EnumMap;
-import java.util.EnumSet;
 import java.util.List;
 import java.util.Map;
 import java.util.Optional;
@@ -31,22 +30,24 @@ public class Run {
     private final Instant start;
     private final Optional<Instant> end;
     private final RunStatus status;
+    private final long lastTestRecord;
 
     // For deserialisation only -- do not use!
-    public Run(RunId id, Map<Step, Step.Status> steps, Versions versions,
-               Instant start, Optional<Instant> end, RunStatus status) {
+    public Run(RunId id, Map<Step, Step.Status> steps, Versions versions, Instant start,
+               Optional<Instant> end, RunStatus status, long lastTestRecord) {
         this.id = id;
         this.steps = Collections.unmodifiableMap(new EnumMap<>(steps));
         this.versions = versions;
         this.start = start;
         this.end = end;
         this.status = status;
+        this.lastTestRecord = lastTestRecord;
     }
 
     public static Run initial(RunId id, Versions versions, Instant now) {
         EnumMap<Step, Step.Status> steps = new EnumMap<>(Step.class);
         JobProfile.of(id.type()).steps().forEach(step -> steps.put(step, unfinished));
-        return new Run(id, steps, requireNonNull(versions), requireNonNull(now), Optional.empty(), running);
+        return new Run(id, steps, requireNonNull(versions), requireNonNull(now), Optional.empty(), running, -1);
     }
 
     /** Returns a new Run with the new status, and with the status of the given, completed step set accordingly. */
@@ -60,21 +61,21 @@ public class Run {
 
         EnumMap<Step, Step.Status> steps = new EnumMap<>(this.steps);
         steps.put(step.get(), Step.Status.of(status));
-        return new Run(id, steps, versions, start, end, this.status == running ? status : this.status); // Keep first terminal status.
+        return new Run(id, steps, versions, start, end, this.status == running ? status : this.status, lastTestRecord);
     }
 
     public Run finished(Instant now) {
         if (hasEnded())
             throw new AssertionError("This run ended at " + end.get() + " -- it can't be ended again!");
 
-        return new Run(id, new EnumMap<>(steps), versions, start, Optional.of(now), status == running ? success : status);
+        return new Run(id, new EnumMap<>(steps), versions, start, Optional.of(now), status == running ? success : status, lastTestRecord);
     }
 
     public Run aborted() {
         if (hasEnded())
             throw new AssertionError("This run ended at " + end.get() + " -- it can't be aborted now!");
 
-        return new Run(id, new EnumMap<>(steps), versions, start, end, aborted);
+        return new Run(id, new EnumMap<>(steps), versions, start, end, aborted, lastTestRecord);
     }
 
     /** Returns the id of this run. */
@@ -116,6 +117,11 @@ public class Run {
         return versions;
     }
 
+    /** Returns the sequence id of the last test record received from the tester, for the test logs of this run. */
+    public long lastTestRecord() {
+        return lastTestRecord;
+    }
+
     @Override
     public boolean equals(Object o) {
         if (this == o) return true;
diff --git a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/persistence/LogRecordSerializer.java b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/persistence/LogRecordSerializer.java
new file mode 100644
index 00000000000..f582b240260
--- /dev/null
+++ b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/persistence/LogRecordSerializer.java
@@ -0,0 +1,64 @@
+package com.yahoo.vespa.hosted.controller.persistence;
+
+import com.google.common.collect.ImmutableList;
+import com.google.common.collect.ImmutableMap;
+import com.yahoo.log.LogLevel;
+import com.yahoo.slime.ArrayTraverser;
+import com.yahoo.slime.Cursor;
+import com.yahoo.slime.Inspector;
+import com.yahoo.slime.ObjectTraverser;
+import com.yahoo.slime.Slime;
+import com.yahoo.vespa.hosted.controller.deployment.Step;
+
+import java.util.List;
+import java.util.Map;
+import java.util.logging.LogRecord;
+
+/**
+ * Serialisation of LogRecord objects. Not all fields are stored!
+ *
+ * @author jonmv
+ */
+class LogRecordSerializer {
+
+    private static final String idField = "id";
+    private static final String levelField = "level";
+    private static final String timestampField = "at";
+    private static final String messageField = "message";
+
+    Slime recordsToSlime(Map<Step, List<LogRecord>> stepRecords) {
+        Slime root = new Slime();
+        Cursor recordsObject = root.setObject();
+        stepRecords.forEach((step, records) -> {
+            Cursor recordsArray = recordsObject.setArray(RunSerializer.valueOf(step));
+            records.forEach(record -> toSlime(record, recordsArray.addObject()));
+        });
+        return root;
+    }
+
+    void toSlime(LogRecord record, Cursor recordObject) {
+        recordObject.setLong(idField, record.getSequenceNumber());
+        recordObject.setString(levelField, LogLevel.getVespaLogLevel(record.getLevel()).getName());
+        recordObject.setLong(timestampField, record.getMillis());
+        recordObject.setString(messageField, record.getMessage());
+    }
+
+    Map<Step, List<LogRecord>> recordsFromSlime(Slime slime) {
+        ImmutableMap.Builder<Step, List<LogRecord>> stepRecords = ImmutableMap.builder();
+        slime.get().traverse((ObjectTraverser) (step, recordsArray) -> {
+            ImmutableList.Builder<LogRecord> records = ImmutableList.builder();
+            recordsArray.traverse((ArrayTraverser) (__, recordObject) -> records.add(fromSlime(recordObject)));
+            stepRecords.put(RunSerializer.stepOf(step), records.build());
+        });
+        return stepRecords.build();
+    }
+
+    private LogRecord fromSlime(Inspector recordObject) {
+        LogRecord record = new LogRecord(LogLevel.parse(recordObject.field(levelField).asString()),
+                                         recordObject.field(messageField).asString());
+        record.setSequenceNumber(recordObject.field(idField).asLong());
+        record.setMillis(recordObject.field(timestampField).asLong());
+        return record;
+    }
+
+}
diff --git a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/persistence/RunSerializer.java b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/persistence/RunSerializer.java
index 12d629f334d..a71e6a393ac 100644
--- a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/persistence/RunSerializer.java
+++ b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/persistence/RunSerializer.java
@@ -51,7 +51,7 @@ import static com.yahoo.vespa.hosted.controller.deployment.Step.endTests;
  *
  * @author jonmv
  */
-public class RunSerializer {
+class RunSerializer {
 
     private static final String stepsField = "steps";
     private static final String applicationField = "id";
@@ -67,6 +67,7 @@ public class RunSerializer {
     private static final String commitField = "commit";
     private static final String buildField = "build";
     private static final String sourceField = "source";
+    private static final String lastTestRecordField = "lastTestRecord";
 
     Run runFromSlime(Slime slime) {
         return runFromSlime(slime.get());
@@ -96,7 +97,8 @@ public class RunSerializer {
                        Optional.of(runObject.field(endField))
                                .filter(Inspector::valid)
                                .map(end -> Instant.ofEpochMilli(end.asLong())),
-                       runStatusOf(runObject.field(statusField).asString()));
+                       runStatusOf(runObject.field(statusField).asString()),
+                       runObject.field(lastTestRecordField).asLong());
     }
 
     private Versions versionsFromSlime(Inspector versionsObject) {
@@ -138,6 +140,7 @@ public class RunSerializer {
         runObject.setLong(startField, run.start().toEpochMilli());
         run.end().ifPresent(end -> runObject.setLong(endField, end.toEpochMilli()));
         runObject.setString(statusField, valueOf(run.status()));
+        runObject.setLong(lastTestRecordField, run.lastTestRecord());
 
         Cursor stepsObject = runObject.setObject(stepsField);
         run.steps().forEach((step, status) -> stepsObject.setString(valueOf(step), valueOf(status)));
diff --git a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/deployment/InternalStepRunnerTest.java b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/deployment/InternalStepRunnerTest.java
index 84487b1802f..66756dc4415 100644
--- a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/deployment/InternalStepRunnerTest.java
+++ b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/deployment/InternalStepRunnerTest.java
@@ -304,7 +304,7 @@ public class InternalStepRunnerTest {
         cloud.set("Failure!".getBytes(), TesterCloud.Status.FAILURE);
         runner.run();
         assertEquals(failed, jobs.run(id).get().steps().get(Step.endTests));
-        assertLogMessages(id, Step.endTests, "Tests still running ...", "Tests failed.", "Failure!");
+        assertLogMessages(id, Step.endTests, "Tests failed.", "Failure!");
     }
 
     @Test
@@ -313,7 +313,7 @@ public class InternalStepRunnerTest {
         cloud.set("Error!".getBytes(), TesterCloud.Status.ERROR);
         runner.run();
         assertEquals(failed, jobs.run(id).get().steps().get(Step.endTests));
-        assertLogMessages(id, Step.endTests, "Tests still running ...", "Tester failed running its tests!", "Error!");
+        assertLogMessages(id, Step.endTests, "Tester failed running its tests!", "Error!");
     }
 
     @Test
@@ -335,7 +335,7 @@ public class InternalStepRunnerTest {
         cloud.set("Success!".getBytes(), TesterCloud.Status.SUCCESS);
         runner.run();
         assertEquals(succeeded, jobs.run(id).get().steps().get(Step.endTests));
-        assertLogMessages(id, Step.endTests, "Tests still running ...", "Tests still running ...", "Tests completed successfully.", "Success!");
+        assertLogMessages(id, Step.endTests, "Tests completed successfully.", "Success!");
     }
 
     private void assertLogMessages(RunId id, Step step, String... messages) {
diff --git a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/persistence/LogSerializerTest.java b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/persistence/LogSerializerTest.java
new file mode 100644
index 00000000000..554e30637f9
--- /dev/null
+++ b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/persistence/LogSerializerTest.java
@@ -0,0 +1,65 @@
+package com.yahoo.vespa.hosted.controller.persistence;
+
+import com.google.common.collect.ImmutableList;
+import com.google.common.collect.ImmutableMap;
+import com.yahoo.log.LogLevel;
+import com.yahoo.vespa.config.SlimeUtils;
+import com.yahoo.vespa.hosted.controller.deployment.Step;
+import org.junit.Test;
+
+import java.io.IOException;
+import java.nio.file.Files;
+import java.nio.file.Path;
+import java.nio.file.Paths;
+import java.util.List;
+import java.util.Map;
+import java.util.logging.Level;
+import java.util.logging.LogRecord;
+
+import static com.yahoo.vespa.hosted.controller.deployment.Step.deployReal;
+import static com.yahoo.vespa.hosted.controller.deployment.Step.deployTester;
+import static org.junit.Assert.assertEquals;
+
+/**
+ * @author jonmv
+ */
+public class LogSerializerTest {
+
+    private static final LogRecordSerializer serializer = new LogRecordSerializer();
+    private static final Path logsFile = Paths.get("src/test/java/com/yahoo/vespa/hosted/controller/persistence/testdata/logs.json");
+
+    @Test
+    public void testSerialization() throws IOException {
+        // Local, because it's not supposed to be used for anything else than verifying equality here!
+        class EgalitarianLogRecord extends LogRecord {
+            private EgalitarianLogRecord(Level level, String msg) {
+                super(level, msg);
+            }
+            @Override
+            public boolean equals(Object o) {
+                if ( ! (o instanceof LogRecord)) return false;
+                LogRecord record = (LogRecord) o;
+                return    getSequenceNumber() == record.getSequenceNumber()
+                          && getLevel() == record.getLevel()
+                          && getMillis() == record.getMillis()
+                          && getMessage().equals(record.getMessage());
+            }
+            @Override
+            public int hashCode() { throw new AssertionError(); }
+        }
+
+        LogRecord  first = new EgalitarianLogRecord(LogLevel.INFO,     "First");   first.setMillis(   0);   first.setSequenceNumber(1);
+        LogRecord second = new EgalitarianLogRecord(LogLevel.INFO,    "Second");  second.setMillis(   0);  second.setSequenceNumber(2);
+        LogRecord  third = new EgalitarianLogRecord(LogLevel.DEBUG,    "Third");   third.setMillis(1000);   third.setSequenceNumber(3);
+        LogRecord fourth = new EgalitarianLogRecord(LogLevel.WARNING, "Fourth");  fourth.setMillis(2000);  fourth.setSequenceNumber(4);
+
+        Map<Step, List<LogRecord>> expected = ImmutableMap.of(deployReal, ImmutableList.of(first, third),
+                                                              deployTester, ImmutableList.of(second, fourth));
+
+        Map<Step, List<LogRecord>> stepRecords = serializer.recordsFromSlime(SlimeUtils.jsonToSlime(Files.readAllBytes(logsFile)));
+        assertEquals(expected, stepRecords);
+
+        assertEquals(expected, serializer.recordsFromSlime(serializer.recordsToSlime(stepRecords)));
+    }
+
+}
diff --git a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/persistence/RunSerializerTest.java b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/persistence/RunSerializerTest.java
index 1085c2a1b70..10537f42c0b 100644
--- a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/persistence/RunSerializerTest.java
+++ b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/persistence/RunSerializerTest.java
@@ -66,6 +66,7 @@ public class RunSerializerTest {
         assertEquals(start, run.start());
         assertFalse(run.hasEnded());
         assertEquals(running, run.status());
+        assertEquals(3, run.lastTestRecord());
         assertEquals(ImmutableMap.<Step, Step.Status>builder()
                              .put(deployInitialReal, unfinished)
                              .put(installInitialReal, failed)
diff --git a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/persistence/testdata/logs.json b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/persistence/testdata/logs.json
new file mode 100644
index 00000000000..1135e63e464
--- /dev/null
+++ b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/persistence/testdata/logs.json
@@ -0,0 +1,32 @@
+{
+  "deployReal":
+  [
+    {
+      "id": 1,
+      "level": "info",
+      "at": 0,
+      "message": "First"
+    },
+    {
+      "id": 3,
+      "level": "debug",
+      "at": 1000,
+      "message": "Third"
+    }
+  ],
+  "deployTester":
+    [
+      {
+        "id": 2,
+        "level": "info",
+        "at": 0,
+        "message": "Second"
+      },
+      {
+        "id": 4,
+        "level": "warning",
+        "at": 2000,
+        "message": "Fourth"
+      }
+    ]
+}
\ No newline at end of file
diff --git a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/persistence/testdata/run-status.json b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/persistence/testdata/run-status.json
index 31e57902d22..0e0149897fc 100644
--- a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/persistence/testdata/run-status.json
+++ b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/persistence/testdata/run-status.json
@@ -5,6 +5,7 @@
     "number": 112358,
     "start": 1196676930000,
     "status": "running",
+    "lastTestRecord": 3,
     "steps": {
       "deployInitialReal": "unfinished",
       "installInitialReal": "failed",
diff --git a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/JobControllerApiHandlerHelperTest.java b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/JobControllerApiHandlerHelperTest.java
index aff7d511d84..f0cb7ca645d 100644
--- a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/JobControllerApiHandlerHelperTest.java
+++ b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/JobControllerApiHandlerHelperTest.java
@@ -142,7 +142,7 @@ public class JobControllerApiHandlerHelperTest {
         RunStatus status = end.isPresent() && lastStepStatus.equals(Optional.of(RunStatus.running))
                 ? RunStatus.success
                 : lastStepStatus.orElse(RunStatus.running);
-        return new Run(runId, stepStatusMap, versions, start, end, status);
+        return new Run(runId, stepStatusMap, versions, start, end, status, -1);
     }
 
     private void compare(HttpResponse response, String expected) {