Copy Vespa logs before deactivating test deployments

8 files changed, 95 insertions, 7 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 d612ffb6930..12290adbc12 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
@@ -12,6 +12,8 @@ import com.yahoo.config.provision.ApplicationId;
 import com.yahoo.config.provision.AthenzDomain;
 import com.yahoo.config.provision.AthenzService;
 import com.yahoo.config.provision.SystemName;
+import com.yahoo.io.IOUtils;
+import com.yahoo.log.LogLevel;
 import com.yahoo.slime.Cursor;
 import com.yahoo.slime.Slime;
 import com.yahoo.vespa.config.SlimeUtils;
@@ -21,6 +23,7 @@ import com.yahoo.vespa.hosted.controller.api.ActivateResult;
 import com.yahoo.vespa.hosted.controller.api.application.v4.model.DeployOptions;
 import com.yahoo.vespa.hosted.controller.api.identifiers.DeploymentId;
 import com.yahoo.vespa.hosted.controller.api.identifiers.Hostname;
+import com.yahoo.vespa.hosted.controller.api.integration.LogEntry;
 import com.yahoo.vespa.hosted.controller.api.integration.configserver.ConfigServerException;
 import com.yahoo.vespa.hosted.controller.api.integration.configserver.Node;
 import com.yahoo.vespa.hosted.controller.api.integration.configserver.PrepareResponse;
@@ -45,6 +48,7 @@ import java.net.URI;
 import java.nio.charset.StandardCharsets;
 import java.time.Duration;
 import java.util.ArrayList;
+import java.util.Collections;
 import java.util.List;
 import java.util.Map;
 import java.util.Optional;
@@ -115,6 +119,7 @@ public class InternalStepRunner implements StepRunner {
                 case installTester: return installTester(id, logger);
                 case startTests: return startTests(id, logger);
                 case endTests: return endTests(id, logger);
+                case copyVespaLogs: return copyVespaLogs(id, logger);
                 case deactivateReal: return deactivateReal(id, logger);
                 case deactivateTester: return deactivateTester(id, logger);
                 case report: return report(id, logger);
@@ -416,6 +421,32 @@ public class InternalStepRunner implements StepRunner {
         }
     }
 
+    private Optional<RunStatus> copyVespaLogs(RunId id, DualLogger logger) {
+        ZoneId zone = id.type().zone(controller.system());
+        logger.log("Copying Vespa log from nodes of " + id.application() + " in " + zone + " ...");
+        try {
+            List<LogEntry> entries = new ArrayList<>();
+            String logs = IOUtils.readAll(controller.configServer().getLogStream(new DeploymentId(id.application(), zone),
+                                                                                 Collections.emptyMap()), // Get all logs.
+                                          StandardCharsets.UTF_8);
+            for (String line : logs.split("\n")) {
+                String[] parts = line.split("\t");
+                if (parts.length != 7) continue;
+                entries.add(new LogEntry(0,
+                                         (long) (Double.parseDouble(parts[0]) * 1000),
+                                         LogEntry.typeOf(LogLevel.parse(parts[5])),
+                                         parts[1] + '\t' + parts[3] + '\t' + parts[4] + '\n' +
+                                         parts[6].replaceAll("\\\\n", "\n")
+                                                 .replaceAll("\\\\t", "\t")));
+            }
+            controller.jobController().log(id, Step.copyVespaLogs, entries);
+        }
+        catch (Exception e) {
+            logger.log(INFO, "Failure getting vespa logs for " + id, e);
+        }
+        return Optional.of(running); // Don't let failure here stop cleanup.
+    }
+
     private Optional<RunStatus> deactivateReal(RunId id, DualLogger logger) {
         logger.log("Deactivating deployment of " + id.application() + " in " + id.type().zone(controller.system()) + " ...");
         controller.applications().deactivate(id.application(), id.type().zone(controller.system()));
diff --git a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/JobController.java b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/JobController.java
index c8ba3f31316..5bff581c4ce 100644
--- a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/JobController.java
+++ b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/JobController.java
@@ -109,18 +109,22 @@ public class JobController {
         }
     }
 
-    /** Stores the given log records for the given run and step. */
-    public void log(RunId id, Step step, Level level, List<String> messages) {
+    /** Stores the given log entries for the given run and step. */
+    public void log(RunId id, Step step, List<LogEntry> entries) {
         locked(id, __ -> {
-            List<LogEntry> entries = messages.stream()
-                                             .map(message -> new LogEntry(0, controller.clock().millis(), LogEntry.typeOf(level), message))
-                                             .collect(toList());
             logs.append(id.application(), id.type(), step, entries);
             return __;
         });
     }
 
-    /** Stores the given log record for the given run and step. */
+    /** Stores the given log messages for the given run and step. */
+    public void log(RunId id, Step step, Level level, List<String> messages) {
+        log(id, step, messages.stream()
+                              .map(message -> new LogEntry(0, controller.clock().millis(), LogEntry.typeOf(level), message))
+                              .collect(toList()));
+    }
+
+    /** Stores the given log message for the given run and step. */
     public void log(RunId id, Step step, Level level, String message) {
         log(id, step, level, Collections.singletonList(message));
     }
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 f606d904c5e..41f57a80ffd 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
@@ -36,6 +36,7 @@ import java.util.Optional;
 import static com.yahoo.vespa.hosted.controller.api.integration.LogEntry.Type.debug;
 import static com.yahoo.vespa.hosted.controller.api.integration.LogEntry.Type.error;
 import static com.yahoo.vespa.hosted.controller.api.integration.LogEntry.Type.info;
+import static com.yahoo.vespa.hosted.controller.api.integration.LogEntry.Type.warning;
 import static com.yahoo.vespa.hosted.controller.deployment.InternalDeploymentTester.appId;
 import static com.yahoo.vespa.hosted.controller.deployment.InternalDeploymentTester.testerId;
 import static com.yahoo.vespa.hosted.controller.deployment.Step.Status.failed;
@@ -286,10 +287,43 @@ public class InternalStepRunnerTest {
                      mailer.inbox("b@a").get(0).subject());
     }
 
+    @Test
+    public void vespaLogIsCopied() {
+        RunId id = tester.startSystemTestTests();
+        tester.cloud().set(TesterCloud.Status.ERROR);
+        tester.configServer().setLogStream(vespaLog);
+        long lastId = tester.jobs().details(id).get().lastId().getAsLong();
+        tester.runner().run();
+        assertEquals(failed, tester.jobs().run(id).get().steps().get(Step.endTests));
+        assertTestLogEntries(id, Step.copyVespaLogs,
+                             new LogEntry(lastId + 2, tester.clock().millis(), debug, "Copying Vespa log from nodes of tenant.application in zone test.us-east-1 in default ..."),
+                             new LogEntry(lastId + 3, 1554970337084L, info,
+                                          "17480180-v6-3.ostk.bm2.prod.ne1.yahoo.com\tcontainer\tContainer.com.yahoo.container.jdisc.ConfiguredApplication\n" +
+                                          "Switching to the latest deployed set of configurations and components. Application switch number: 2"),
+                             new LogEntry(lastId + 4, 1554970337935L, info,
+                                          "17491290-v6-1.ostk.bm2.prod.ne1.yahoo.com\tcontainer\tstdout\n" +
+                                          "ERROR: Bundle canary-application [71] Unable to get module class path. (java.lang.NullPointerException)"),
+                             new LogEntry(lastId + 5, 1554970337947L, info,
+                                          "17491290-v6-1.ostk.bm2.prod.ne1.yahoo.com\tcontainer\tstdout\n" +
+                                          "ERROR: Bundle canary-application [71] Unable to get module class path. (java.lang.NullPointerException)"),
+                             new LogEntry(lastId + 6, 1554970337947L, info,
+                                          "17491290-v6-1.ostk.bm2.prod.ne1.yahoo.com\tcontainer\tstdout\n" +
+                                          "ERROR: Bundle canary-application [71] Unable to get module class path. (java.lang.NullPointerException)"),
+                             new LogEntry(lastId + 7, 1554970337947L, warning,
+                                          "17491290-v6-1.ostk.bm2.prod.ne1.yahoo.com\tcontainer\tstderr\n" +
+                                          "java.lang.NullPointerException\n\tat org.apache.felix.framework.BundleRevisionImpl.calculateContentPath(BundleRevisionImpl.java:438)\n\tat org.apache.felix.framework.BundleRevisionImpl.initializeContentPath(BundleRevisionImpl.java:371)"));
+    }
+
     private void assertTestLogEntries(RunId id, Step step, LogEntry... entries) {
         assertEquals(List.of(entries), tester.jobs().details(id).get().get(step));
     }
 
+    private static final String vespaLog = "1554970337.084804\t17480180-v6-3.ostk.bm2.prod.ne1.yahoo.com\t5549/832\tcontainer\tContainer.com.yahoo.container.jdisc.ConfiguredApplication\tinfo\tSwitching to the latest deployed set of configurations and components. Application switch number: 2\n" +
+                                           "1554970337.935104\t17491290-v6-1.ostk.bm2.prod.ne1.yahoo.com\t5480\tcontainer\tstdout\tinfo\tERROR: Bundle canary-application [71] Unable to get module class path. (java.lang.NullPointerException)\n" +
+                                           "1554970337.947777\t17491290-v6-1.ostk.bm2.prod.ne1.yahoo.com\t5480\tcontainer\tstdout\tinfo\tERROR: Bundle canary-application [71] Unable to get module class path. (java.lang.NullPointerException)\n" +
+                                           "1554970337.947820\t17491290-v6-1.ostk.bm2.prod.ne1.yahoo.com\t5480\tcontainer\tstdout\tinfo\tERROR: Bundle canary-application [71] Unable to get module class path. (java.lang.NullPointerException)\n" +
+                                           "1554970337.947844\t17491290-v6-1.ostk.bm2.prod.ne1.yahoo.com\t5480\tcontainer\tstderr\twarning\tjava.lang.NullPointerException\\n\\tat org.apache.felix.framework.BundleRevisionImpl.calculateContentPath(BundleRevisionImpl.java:438)\\n\\tat org.apache.felix.framework.BundleRevisionImpl.initializeContentPath(BundleRevisionImpl.java:371)";
+
     @Test
     public void generates_correct_services_xml_test() {
         assertFile("test_runner_services.xml-cd", new String(InternalStepRunner.servicesXml(SystemName.cd, Optional.of("d-2-12-75"))));
diff --git a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/integration/ConfigServerMock.java b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/integration/ConfigServerMock.java
index 927596ca9ab..1222ae30c8a 100644
--- a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/integration/ConfigServerMock.java
+++ b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/integration/ConfigServerMock.java
@@ -63,6 +63,7 @@ public class ConfigServerMock extends AbstractComponent implements ConfigServer
     private Version lastPrepareVersion = null;
     private RuntimeException prepareException = null;
     private ConfigChangeActions configChangeActions = null;
+    private String log = "INFO - All good";
 
     @Inject
     public ConfigServerMock(ZoneRegistryMock zoneRegistry) {
@@ -361,7 +362,11 @@ public class ConfigServerMock extends AbstractComponent implements ConfigServer
 
     @Override
     public InputStream getLogStream(DeploymentId deployment, Map<String, String> queryParameters) {
-        return IOUtils.toInputStream("INFO - All good");
+        return IOUtils.toInputStream(log);
+    }
+
+    public void setLogStream(String log) {
+        this.log = log;
     }
 
     @Override
diff --git a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/jobs.json b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/jobs.json
index 1c8da68e138..5ac896e2753 100644
--- a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/jobs.json
+++ b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/jobs.json
@@ -57,6 +57,7 @@
             "installTester": "unfinished",
             "startTests": "unfinished",
             "endTests": "unfinished",
+            "copyVespaLogs": "unfinished",
             "deactivateReal": "unfinished",
             "deactivateTester": "unfinished",
             "report": "unfinished"
@@ -94,6 +95,7 @@
             "installTester": "unfinished",
             "startTests": "unfinished",
             "endTests": "unfinished",
+            "copyVespaLogs": "unfinished",
             "deactivateReal": "unfinished",
             "deactivateTester": "unfinished",
             "report": "unfinished"
diff --git a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/overview.json b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/overview.json
index c7580d869b0..84866650afc 100644
--- a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/overview.json
+++ b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/overview.json
@@ -116,6 +116,7 @@
             "installTester": "succeeded",
             "startTests": "succeeded",
             "endTests": "succeeded",
+            "copyVespaLogs": "succeeded",
             "deactivateReal": "succeeded",
             "deactivateTester": "succeeded",
             "report": "succeeded"
@@ -159,6 +160,7 @@
             "installTester": "succeeded",
             "startTests": "succeeded",
             "endTests": "succeeded",
+            "copyVespaLogs": "succeeded",
             "deactivateReal": "succeeded",
             "deactivateTester": "succeeded",
             "report": "succeeded"
@@ -192,6 +194,7 @@
             "installTester": "succeeded",
             "startTests": "succeeded",
             "endTests": "succeeded",
+            "copyVespaLogs": "succeeded",
             "deactivateReal": "succeeded",
             "deactivateTester": "succeeded",
             "report": "succeeded"
@@ -269,6 +272,7 @@
             "installTester": "unfinished",
             "startTests": "unfinished",
             "endTests": "unfinished",
+            "copyVespaLogs": "succeeded",
             "deactivateReal": "succeeded",
             "deactivateTester": "succeeded",
             "report": "succeeded"
@@ -310,6 +314,7 @@
             "installTester": "succeeded",
             "startTests": "succeeded",
             "endTests": "succeeded",
+            "copyVespaLogs": "succeeded",
             "deactivateReal": "succeeded",
             "deactivateTester": "succeeded",
             "report": "succeeded"
@@ -355,6 +360,7 @@
             "installTester": "succeeded",
             "startTests": "succeeded",
             "endTests": "succeeded",
+            "copyVespaLogs": "succeeded",
             "deactivateReal": "succeeded",
             "deactivateTester": "succeeded",
             "report": "succeeded"
@@ -390,6 +396,7 @@
             "installTester": "succeeded",
             "startTests": "succeeded",
             "endTests": "succeeded",
+            "copyVespaLogs": "succeeded",
             "deactivateReal": "succeeded",
             "deactivateTester": "succeeded",
             "report": "succeeded"
diff --git a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/staging-runs.json b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/staging-runs.json
index 8c5e5253482..68599618ab4 100644
--- a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/staging-runs.json
+++ b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/staging-runs.json
@@ -23,6 +23,7 @@
       "installTester": "succeeded",
       "startTests": "succeeded",
       "endTests": "succeeded",
+      "copyVespaLogs": "succeeded",
       "deactivateReal": "succeeded",
       "deactivateTester": "succeeded",
       "report": "succeeded"
@@ -68,6 +69,7 @@
       "installTester": "succeeded",
       "startTests": "succeeded",
       "endTests": "succeeded",
+      "copyVespaLogs": "succeeded",
       "deactivateReal": "succeeded",
       "deactivateTester": "succeeded",
       "report": "succeeded"
@@ -113,6 +115,7 @@
       "installTester": "succeeded",
       "startTests": "succeeded",
       "endTests": "succeeded",
+      "copyVespaLogs": "succeeded",
       "deactivateReal": "succeeded",
       "deactivateTester": "succeeded",
       "report": "succeeded"
@@ -158,6 +161,7 @@
       "installTester": "unfinished",
       "startTests": "unfinished",
       "endTests": "unfinished",
+      "copyVespaLogs": "succeeded",
       "deactivateReal": "succeeded",
       "deactivateTester": "succeeded",
       "report": "succeeded"
diff --git a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/system-test-job.json b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/system-test-job.json
index 71f647ead11..2f5c6e489bd 100644
--- a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/system-test-job.json
+++ b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/system-test-job.json
@@ -20,6 +20,7 @@
       "installTester": "unfinished",
       "startTests": "unfinished",
       "endTests": "unfinished",
+      "copyVespaLogs": "unfinished",
       "deactivateReal": "unfinished",
       "deactivateTester": "unfinished",
       "report": "unfinished"