Merge pull request #22722 from vespa-engine/jonmv/deactivate-tester-depends-on-vespa-log-now

Jonmv/deactivate tester depends on vespa log now

8 files changed, 62 insertions, 39 deletions

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 30f16acf77d..8359ea0a478 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
@@ -69,8 +69,12 @@ import static com.yahoo.vespa.hosted.controller.deployment.Step.copyVespaLogs;
 import static com.yahoo.vespa.hosted.controller.deployment.Step.deactivateTester;
 import static com.yahoo.vespa.hosted.controller.deployment.Step.endStagingSetup;
 import static com.yahoo.vespa.hosted.controller.deployment.Step.endTests;
+import static com.yahoo.vespa.hosted.controller.deployment.Step.installInitialReal;
+import static com.yahoo.vespa.hosted.controller.deployment.Step.installReal;
+import static com.yahoo.vespa.hosted.controller.deployment.Step.installTester;
 import static com.yahoo.vespa.hosted.controller.deployment.Step.report;
 import static java.time.temporal.ChronoUnit.SECONDS;
+import static java.util.Comparator.comparing;
 import static java.util.Comparator.naturalOrder;
 import static java.util.function.Predicate.not;
 import static java.util.logging.Level.INFO;
@@ -179,11 +183,27 @@ public class JobController {
             if (deployment.isEmpty() || deployment.get().at().isBefore(run.start()))
                 return run;
 
-            Instant from = run.lastVespaLogTimestamp().isAfter(deployment.get().at()) ? run.lastVespaLogTimestamp() : deployment.get().at();
+            Instant deployedAt = run.stepInfo(installInitialReal).or(() -> run.stepInfo(installReal)).flatMap(StepInfo::startTime).orElseThrow();
+            Instant from = run.lastVespaLogTimestamp().isAfter(run.start()) ? run.lastVespaLogTimestamp() : deployedAt.minusSeconds(10);
             List<LogEntry> log = LogEntry.parseVespaLog(controller.serviceRegistry().configServer()
                                                                   .getLogs(new DeploymentId(id.application(), zone),
                                                                            Map.of("from", Long.toString(from.toEpochMilli()))),
                                                         from);
+
+            if (run.hasStep(installTester) && run.versions().targetPlatform().isAfter(new Version("7.589.14"))) { // todo jonmv: remove
+                deployedAt = run.stepInfo(installTester).flatMap(StepInfo::startTime).orElseThrow();
+                from = run.lastVespaLogTimestamp().isAfter(run.start()) ? run.lastVespaLogTimestamp() : deployedAt.minusSeconds(10);
+                List<LogEntry> testerLog = LogEntry.parseVespaLog(controller.serviceRegistry().configServer()
+                                                                            .getLogs(new DeploymentId(id.tester().id(), zone),
+                                                                                     Map.of("from", Long.toString(from.toEpochMilli()))),
+                                                                  from);
+
+                Instant justNow = controller.clock().instant().minusSeconds(2);
+                log = Stream.concat(log.stream(), testerLog.stream())
+                            .filter(entry -> entry.at().isBefore(justNow))
+                            .sorted(comparing(LogEntry::at))
+                            .collect(toUnmodifiableList());
+            }
             if (log.isEmpty())
                 return run;
 
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 03cc6c6ba8d..7ffaaabb1a7 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
@@ -45,8 +45,9 @@ public class Run {
 
     // For deserialisation only -- do not use!
     public Run(RunId id, Map<Step, StepInfo> steps, Versions versions, boolean isRedeployment, Instant start, Optional<Instant> end,
-               Optional<Instant> sleepUntil, RunStatus status, long lastTestRecord, Instant lastVespaLogTimestamp, Optional<Instant> noNodesDownSince,
-               Optional<ConvergenceSummary> convergenceSummary, Optional<X509Certificate> testerCertificate, boolean dryRun, Optional<String> reason) {
+               Optional<Instant> sleepUntil, RunStatus status, long lastTestRecord, Instant lastVespaLogTimestamp,
+               Optional<Instant> noNodesDownSince, Optional<ConvergenceSummary> convergenceSummary,
+               Optional<X509Certificate> testerCertificate, boolean dryRun, Optional<String> reason) {
         this.id = id;
         this.steps = Collections.unmodifiableMap(new EnumMap<>(steps));
         this.versions = versions;
@@ -67,8 +68,9 @@ public class Run {
     public static Run initial(RunId id, Versions versions, boolean isRedeployment, Instant now, JobProfile profile, Optional<String> triggeredBy) {
         EnumMap<Step, StepInfo> steps = new EnumMap<>(Step.class);
         profile.steps().forEach(step -> steps.put(step, StepInfo.initial(step)));
-        return new Run(id, steps, requireNonNull(versions), isRedeployment, requireNonNull(now), Optional.empty(), Optional.empty(), running,
-                       -1, Instant.EPOCH, Optional.empty(), Optional.empty(), Optional.empty(), profile == JobProfile.developmentDryRun, triggeredBy);
+        return new Run(id, steps, requireNonNull(versions), isRedeployment, requireNonNull(now), Optional.empty(),
+                       Optional.empty(), running, -1, Instant.EPOCH, Optional.empty(), Optional.empty(),
+                       Optional.empty(), profile == JobProfile.developmentDryRun, triggeredBy);
     }
 
     /** Returns a new Run with the status of the given completed step set accordingly. */
diff --git a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/Step.java b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/Step.java
index 379cc9c4f0a..ec4d138c44f 100644
--- a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/Step.java
+++ b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/Step.java
@@ -65,7 +65,7 @@ public enum Step {
     deactivateReal(true, deployInitialReal, deployReal, endTests, copyVespaLogs),
 
     /** Deactivate the tester. */
-    deactivateTester(true, deployTester, endTests),
+    deactivateTester(true, deployTester, endTests, copyVespaLogs),
 
     /** Report completion to the deployment orchestration machinery. */
     report(true, installReal, deactivateReal, deactivateTester);
diff --git a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/maintenance/JobRunner.java b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/maintenance/JobRunner.java
index 369699eb3a3..e954a1b6849 100644
--- a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/maintenance/JobRunner.java
+++ b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/maintenance/JobRunner.java
@@ -83,7 +83,6 @@ public class JobRunner extends ControllerMaintainer {
                 jobs.abort(run.id(), "job timeout of " + jobTimeout + " reached");
                 advance(jobs.run(run.id()).get());
             });
-
         else if (run.readySteps().isEmpty())
             executors.execute(() -> finish(run.id()));
         else if (run.hasFailed() || run.sleepUntil().map(sleepUntil -> ! sleepUntil.isAfter(controller().clock().instant())).orElse(true))
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 dd28978d948..fcc6d99aec2 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
@@ -3,7 +3,6 @@ package com.yahoo.vespa.hosted.controller.persistence;
 
 import com.yahoo.component.Version;
 import com.yahoo.config.provision.ApplicationId;
-import com.yahoo.config.provision.SystemName;
 import com.yahoo.security.X509CertificateUtils;
 import com.yahoo.slime.ArrayTraverser;
 import com.yahoo.slime.Cursor;
@@ -214,7 +213,7 @@ class RunSerializer {
         run.sleepUntil().ifPresent(end -> runObject.setLong(sleepingUntilField, end.toEpochMilli()));
         runObject.setString(statusField, valueOf(run.status()));
         runObject.setLong(lastTestRecordField, run.lastTestLogEntry());
-        runObject.setLong(lastVespaLogTimestampField, Instant.EPOCH.until(run.lastVespaLogTimestamp(), ChronoUnit.MICROS));
+        if (run.lastVespaLogTimestamp().isAfter(Instant.EPOCH)) runObject.setLong(lastVespaLogTimestampField, Instant.EPOCH.until(run.lastVespaLogTimestamp(), ChronoUnit.MICROS));
         run.noNodesDownSince().ifPresent(noNodesDownSince -> runObject.setLong(noNodesDownSinceField, noNodesDownSince.toEpochMilli()));
         run.convergenceSummary().ifPresent(convergenceSummary -> toSlime(convergenceSummary, runObject.setArray(convergenceSummaryField)));
         run.testerCertificate().ifPresent(certificate -> runObject.setString(testerCertificateField, X509CertificateUtils.toPem(certificate)));
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 031cdaa84ae..ae08d1b3a22 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
@@ -6,7 +6,6 @@ import com.yahoo.config.application.api.DeploymentSpec;
 import com.yahoo.config.provision.AthenzDomain;
 import com.yahoo.config.provision.AthenzService;
 import com.yahoo.config.provision.HostName;
-import com.yahoo.config.provision.NodeResources;
 import com.yahoo.config.provision.SystemName;
 import com.yahoo.config.provision.zone.RoutingMethod;
 import com.yahoo.config.provision.zone.ZoneId;
@@ -24,23 +23,14 @@ import com.yahoo.vespa.hosted.controller.api.integration.deployment.TesterCloud.
 import com.yahoo.vespa.hosted.controller.api.integration.stubs.MockMailer;
 import com.yahoo.vespa.hosted.controller.application.SystemApplication;
 import com.yahoo.vespa.hosted.controller.application.pkg.ApplicationPackage;
-import com.yahoo.vespa.hosted.controller.application.pkg.TestPackage;
-import com.yahoo.vespa.hosted.controller.config.ControllerConfig;
 import com.yahoo.vespa.hosted.controller.integration.ZoneApiMock;
 import com.yahoo.vespa.hosted.controller.maintenance.JobRunner;
 import org.junit.Before;
 import org.junit.Test;
 
-import java.io.IOException;
-import java.io.UncheckedIOException;
-import java.nio.charset.StandardCharsets;
-import java.nio.file.Files;
-import java.nio.file.Path;
-import java.nio.file.Paths;
 import java.security.cert.X509Certificate;
 import java.time.Duration;
 import java.time.Instant;
-import java.time.temporal.ChronoUnit;
 import java.util.ArrayList;
 import java.util.List;
 import java.util.Optional;
@@ -60,7 +50,6 @@ import static com.yahoo.vespa.hosted.controller.deployment.RunStatus.success;
 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.nio.charset.StandardCharsets.UTF_8;
 import static java.time.temporal.ChronoUnit.SECONDS;
 import static org.junit.Assert.assertEquals;
 import static org.junit.Assert.assertFalse;
@@ -455,6 +444,7 @@ public class InternalStepRunnerTest {
     @Test
     public void vespaLogIsCopied() {
         // Tests fail. We should get logs. This fails too, on the first attempt.
+        tester.controllerTester().computeVersionStatus();
         RunId id = app.startSystemTestTests();
         tester.cloud().set(TesterCloud.Status.ERROR);
         tester.configServer().setLogStream(() -> { throw new ConfigServerException(ConfigServerException.ErrorCode.NOT_FOUND, "404", "context"); });
@@ -464,31 +454,43 @@ public class InternalStepRunnerTest {
         assertEquals(unfinished, tester.jobs().run(id).get().stepStatuses().get(Step.copyVespaLogs));
         assertTestLogEntries(id, Step.copyVespaLogs,
                              new LogEntry(lastId + 2, tester.clock().instant(), info,
-                                          "Found no logs, but will retry"),
-                             new LogEntry(lastId + 4, tester.clock().instant(), info,
                                           "Found no logs, but will retry"));
 
         // Config servers now provide the log, and we get it.
-        tester.configServer().setLogStream(() -> vespaLog);
+        tester.configServer().setLogStream(() -> vespaLog(tester.clock().instant()));
         tester.runner().run();
         assertEquals(failed, tester.jobs().run(id).get().stepStatuses().get(Step.endTests));
         assertTestLogEntries(id, Step.copyVespaLogs,
                              new LogEntry(lastId + 2, tester.clock().instant(), info,
                                           "Found no logs, but will retry"),
-                             new LogEntry(lastId + 4, tester.clock().instant(), info,
-                                          "Found no logs, but will retry"),
-                             new LogEntry(lastId + 5, Instant.EPOCH.plus(3554970337935104L, ChronoUnit.MICROS), info,
+                             new LogEntry(lastId + 3, tester.clock().instant().minusSeconds(4), 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 + 4, tester.clock().instant().minusSeconds(4), 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, tester.clock().instant().minusSeconds(4), 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, tester.clock().instant().minusSeconds(4), 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, Instant.EPOCH.plus(3554970337947777L, ChronoUnit.MICROS), info,
+                              */
+                             new LogEntry(lastId + 5, tester.clock().instant().minusSeconds(3), 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, Instant.EPOCH.plus(3554970337947820L, ChronoUnit.MICROS), info,
+                             new LogEntry(lastId + 6, tester.clock().instant().minusSeconds(3), 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)"));
+                             /*
+                             new LogEntry(lastId + 9, tester.clock().instant().minusSeconds(3), 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 + 8, Instant.EPOCH.plus(3554970337947845L, ChronoUnit.MICROS), warning,
+                             new LogEntry(lastId + 10, tester.clock().instant().minusSeconds(3), 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)"));
+                             */
     }
 
     @Test
@@ -548,10 +550,12 @@ public class InternalStepRunnerTest {
         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" +
-                                           "3554970337.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" +
-                                           "3554970337.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" +
-                                           "3554970337.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" +
-                                           "3554970337.947845\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)";
+    private static String vespaLog(Instant now) {
+        return "-1\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" +
+               (now.getEpochSecond() - 4) + "." + now.getNano() / 1000 + "\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" +
+               (now.getEpochSecond() - 4) + "." + now.getNano() / 1000 + "\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" +
+               (now.getEpochSecond() - 3) + "." + now.getNano() / 1000 + "\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" +
+               (now.getEpochSecond() - 3) + "." + now.getNano() / 1000 + "\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)";
+    }
 
 }
diff --git a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/maintenance/JobRunnerTest.java b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/maintenance/JobRunnerTest.java
index 3ed5854327b..b9ced334e5a 100644
--- a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/maintenance/JobRunnerTest.java
+++ b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/maintenance/JobRunnerTest.java
@@ -93,8 +93,7 @@ public class JobRunnerTest {
         ApplicationId id = appId.defaultInstance();
         byte[] testPackageBytes = new byte[0];
         jobs.submit(appId, Submission.basic(applicationPackage, testPackageBytes), 2);
-
-                    start(jobs, id, systemTest);
+        start(jobs, id, systemTest);
         try {
             start(jobs, id, systemTest);
             fail("Job is already running, so this should not be allowed!");
@@ -169,8 +168,8 @@ public class JobRunnerTest {
         outcomes.put(endTests, testFailure);
         runner.maintain();
         assertTrue(run.get().hasFailed());
-        assertEquals(List.of(copyVespaLogs, deactivateTester), run.get().readySteps());
-        assertStepsWithStartTime(run.get(), deployTester, deployReal, installTester, installReal, startTests, endTests, copyVespaLogs, deactivateTester);
+        assertEquals(List.of(copyVespaLogs), run.get().readySteps());
+        assertStepsWithStartTime(run.get(), deployTester, deployReal, installTester, installReal, startTests, endTests, copyVespaLogs);
 
         outcomes.put(copyVespaLogs, running);
         runner.maintain();
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 fd0ea50e50b..6a01a70eb98 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
@@ -25,7 +25,6 @@ import java.time.Instant;
 import java.util.List;
 import java.util.Optional;
 
-import static com.yahoo.config.provision.SystemName.main;
 import static com.yahoo.vespa.hosted.controller.deployment.RunStatus.aborted;
 import static com.yahoo.vespa.hosted.controller.deployment.RunStatus.running;
 import static com.yahoo.vespa.hosted.controller.deployment.Step.Status.failed;
@@ -132,6 +131,7 @@ public class RunSerializerTest {
         assertEquals(run.end(), phoenix.end());
         assertEquals(run.status(), phoenix.status());
         assertEquals(run.lastTestLogEntry(), phoenix.lastTestLogEntry());
+        assertEquals(run.lastVespaLogTimestamp(), phoenix.lastVespaLogTimestamp());
         assertEquals(run.noNodesDownSince(), phoenix.noNodesDownSince());
         assertEquals(run.testerCertificate(), phoenix.testerCertificate());
         assertEquals(run.versions(), phoenix.versions());