diff options
author | Jon Marius Venstad <jonmv@users.noreply.github.com> | 2019-09-13 20:08:47 +0200 |
---|---|---|
committer | GitHub <noreply@github.com> | 2019-09-13 20:08:47 +0200 |
commit | a837584e11f421908532eadf4b2859ed9d4729a3 (patch) | |
tree | b1b4eb80301d27323f8e707b7feba9f9ecdad9d0 /controller-server/src | |
parent | ed96db11181a3008eedf25ab9e2a24cdad928f56 (diff) | |
parent | 078da6a5b6884f7d5441d0d0c16007dbe536773b (diff) |
Merge pull request #10641 from vespa-engine/jvenstad/live-vespa-logs-in-deployments
Jvenstad/live vespa logs in deployments
Diffstat (limited to 'controller-server/src')
20 files changed, 252 insertions, 94 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 251bdbd2249..be558707415 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 @@ -14,8 +14,6 @@ import com.yahoo.config.provision.AthenzService; import com.yahoo.config.provision.ClusterSpec; import com.yahoo.config.provision.NodeResources; import com.yahoo.config.provision.zone.ZoneId; -import com.yahoo.io.IOUtils; -import com.yahoo.log.LogLevel; import com.yahoo.security.KeyAlgorithm; import com.yahoo.security.KeyUtils; import com.yahoo.security.SignatureAlgorithm; @@ -27,7 +25,6 @@ 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; @@ -54,7 +51,6 @@ import java.security.cert.CertificateNotYetValidException; import java.security.cert.X509Certificate; import java.time.Duration; import java.util.ArrayList; -import java.util.Collections; import java.util.Date; import java.util.List; import java.util.Locale; @@ -505,25 +501,9 @@ public class InternalStepRunner implements StepRunner { } private Optional<RunStatus> copyVespaLogs(RunId id, DualLogger logger) { - ZoneId zone = id.type().zone(controller.system()); if (deployment(id.application(), id.type()).isPresent()) try { - logger.log("Copying Vespa log from nodes of " + id.application() + " in " + zone + " ..."); - List<LogEntry> entries = new ArrayList<>(); - String logs = IOUtils.readAll(controller.serviceRegistry().configServer().getLogs(new DeploymentId(id.application(), zone), - Collections.emptyMap()), // Get all logs. - 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); + controller.jobController().updateVespaLog(id); } catch (Exception e) { logger.log(INFO, "Failure getting vespa logs for " + id, e); 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 2f8c08c15be..bd0e487248f 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 @@ -28,6 +28,7 @@ import com.yahoo.vespa.hosted.controller.persistence.CuratorDb; import java.net.URI; import java.security.cert.X509Certificate; import java.time.Duration; +import java.time.Instant; import java.util.ArrayList; import java.util.Collections; import java.util.Comparator; @@ -46,6 +47,7 @@ import java.util.stream.Collectors; import java.util.stream.Stream; import static com.google.common.collect.ImmutableList.copyOf; +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.endTests; import static java.util.stream.Collectors.toList; @@ -127,7 +129,7 @@ public class JobController { /** 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)) + .map(message -> new LogEntry(0, controller.clock().instant(), LogEntry.typeOf(level), message)) .collect(toList())); } @@ -136,6 +138,31 @@ public class JobController { log(id, step, level, Collections.singletonList(message)); } + /** Fetches any new Vespa log entries, and records the timestamp of the last of these, for continuation. */ + public void updateVespaLog(RunId id) { + locked(id, run -> { + if ( ! run.steps().containsKey(copyVespaLogs)) + return run; + + ZoneId zone = id.type().zone(controller.system()); + Optional<Deployment> deployment = Optional.ofNullable(controller.applications().require(id.application()) + .deployments().get(zone)); + if (deployment.isEmpty() || deployment.get().at().isBefore(run.start())) + return run; + + Instant from = run.lastVespaLogTimestamp().isAfter(deployment.get().at()) ? run.lastVespaLogTimestamp() : deployment.get().at(); + List<LogEntry> log = LogEntry.parseVespaLog(controller.serviceRegistry().configServer() + .getLogs(new DeploymentId(id.application(), zone), + Map.of("from", Long.toString(from.toEpochMilli()))), + from); + if (log.isEmpty()) + return run; + + logs.append(id.application(), id.type(), Step.copyVespaLogs, log); + return run.with(log.get(log.size() - 1).at()); + }); + } + /** Fetches any new test log entries, and records the id of the last of these, for continuation. */ public void updateTestLog(RunId id) { locked(id, run -> { diff --git a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/JobProfile.java b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/JobProfile.java index ed2cd8eaa76..685fee92e7e 100644 --- a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/JobProfile.java +++ b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/JobProfile.java @@ -51,7 +51,7 @@ public enum JobProfile { development(EnumSet.of(deployReal, installReal), - EnumSet.noneOf(Step.class)); + EnumSet.of(copyVespaLogs)); private final Set<Step> steps; 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 d9162df0bc4..d7d6134ccb9 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 @@ -34,11 +34,13 @@ public class Run { private final Optional<Instant> end; private final RunStatus status; private final long lastTestRecord; + private final Instant lastVespaLogTimestamp; private final Optional<X509Certificate> testerCertificate; // For deserialisation only -- do not use! public Run(RunId id, Map<Step, Step.Status> steps, Versions versions, Instant start, - Optional<Instant> end, RunStatus status, long lastTestRecord, Optional<X509Certificate> testerCertificate) { + Optional<Instant> end, RunStatus status, long lastTestRecord, Instant lastVespaLogTimestamp, + Optional<X509Certificate> testerCertificate) { this.id = id; this.steps = Collections.unmodifiableMap(new EnumMap<>(steps)); this.versions = versions; @@ -46,55 +48,58 @@ public class Run { this.end = end; this.status = status; this.lastTestRecord = lastTestRecord; + this.lastVespaLogTimestamp = lastVespaLogTimestamp; this.testerCertificate = testerCertificate; } 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, -1, Optional.empty()); + return new Run(id, steps, requireNonNull(versions), requireNonNull(now), Optional.empty(), running, + -1, Instant.EPOCH, Optional.empty()); } /** Returns a new Run with the new status, and with the status of the given, completed step set accordingly. */ public Run with(RunStatus status, LockedStep step) { - if (hasEnded()) - throw new IllegalStateException("This run ended at " + end.get() + " -- it can't be further modified!"); - + requireActive(); if (steps.get(step.get()) != unfinished) throw new IllegalStateException("Step '" + step.get() + "' can't be set to '" + status + "'" + " -- it already completed with status '" + steps.get(step.get()) + "'!"); 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, lastTestRecord, testerCertificate); + return new Run(id, steps, versions, start, end, this.status == running ? status : this.status, + lastTestRecord, lastVespaLogTimestamp, testerCertificate); } public Run finished(Instant now) { - if (hasEnded()) - throw new IllegalStateException("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, lastTestRecord, testerCertificate); + requireActive(); + return new Run(id, new EnumMap<>(steps), versions, start, Optional.of(now), status == running ? success : status, + lastTestRecord, lastVespaLogTimestamp, testerCertificate); } public Run aborted() { - if (hasEnded()) - throw new IllegalStateException("This run ended at " + end.get() + " -- it can't be aborted now!"); - - return new Run(id, new EnumMap<>(steps), versions, start, end, aborted, lastTestRecord, testerCertificate); + requireActive(); + return new Run(id, new EnumMap<>(steps), versions, start, end, aborted, + lastTestRecord, lastVespaLogTimestamp, testerCertificate); } public Run with(long lastTestRecord) { - if (hasEnded()) - throw new IllegalStateException("This run ended at " + end.get() + " -- it can't be further modified!"); + requireActive(); + return new Run(id, new EnumMap<>(steps), versions, start, end, status, + lastTestRecord, lastVespaLogTimestamp, testerCertificate); + } - return new Run(id, new EnumMap<>(steps), versions, start, end, status, lastTestRecord, testerCertificate); + public Run with(Instant lastVespaLogTimestamp) { + requireActive(); + return new Run(id, new EnumMap<>(steps), versions, start, end, status, + lastTestRecord, lastVespaLogTimestamp, testerCertificate); } public Run with(X509Certificate testerCertificate) { - if (hasEnded()) - throw new IllegalStateException("This run ended at " + end.get() + " -- it can't be further modified!"); - - return new Run(id, new EnumMap<>(steps), versions, start, end, status, lastTestRecord, Optional.of(testerCertificate)); + requireActive(); + return new Run(id, new EnumMap<>(steps), versions, start, end, status, + lastTestRecord, lastVespaLogTimestamp, Optional.of(testerCertificate)); } /** Returns the id of this run. */ @@ -141,6 +146,11 @@ public class Run { return lastTestRecord; } + /** Returns the timestamp of the last Vespa log record fetched and stored for this run. */ + public Instant lastVespaLogTimestamp() { + return lastVespaLogTimestamp; + } + /** Returns the tester certificate for this run, or empty. */ public Optional<X509Certificate> testerCertificate() { return testerCertificate; @@ -201,4 +211,9 @@ public class Run { .iterator()); } + private void requireActive() { + if (hasEnded()) + throw new IllegalStateException("This run ended at " + end.get() + " -- it can't be further modified!"); + } + } 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 b37e3a1105d..8870425c82b 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 @@ -49,8 +49,8 @@ public enum Step { /** See that the tests are done running. */ endTests(startTests), - /** Fetch and store Vespa logs from the log server cluster of the deployment -- used for test deployments. */ - copyVespaLogs(deployInitialReal, deployReal, endTests), + /** Fetch and store Vespa logs from the log server cluster of the deployment -- used for test and dev deployments. */ + copyVespaLogs(installReal, endTests), /** Delete the real application -- used for test deployments. */ deactivateReal(deployInitialReal, deployReal, endTests, copyVespaLogs), diff --git a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/persistence/LogSerializer.java b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/persistence/LogSerializer.java index 418038d4f1e..e32e8ceacca 100644 --- a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/persistence/LogSerializer.java +++ b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/persistence/LogSerializer.java @@ -13,6 +13,7 @@ import com.yahoo.vespa.hosted.controller.deployment.Step; import java.io.IOException; import java.io.UncheckedIOException; +import java.time.Instant; import java.util.ArrayList; import java.util.Collections; import java.util.HashMap; @@ -60,7 +61,7 @@ class LogSerializer { private void toSlime(LogEntry entry, Cursor entryObject) { entryObject.setLong(idField, entry.id()); - entryObject.setLong(timestampField, entry.at()); + entryObject.setLong(timestampField, entry.at().toEpochMilli()); entryObject.setString(typeField, valueOf(entry.type())); entryObject.setString(messageField, entry.message()); } @@ -92,7 +93,7 @@ class LogSerializer { private LogEntry fromSlime(Inspector entryObject) { return new LogEntry(entryObject.field(idField).asLong(), - entryObject.field(timestampField).asLong(), + Instant.ofEpochMilli(entryObject.field(timestampField).asLong()), typeOf(entryObject.field(typeField).asString()), entryObject.field(messageField).asString()); } 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 aa7d29585cb..dda1fb881a7 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 @@ -20,6 +20,7 @@ import com.yahoo.vespa.hosted.controller.deployment.Step.Status; import com.yahoo.vespa.hosted.controller.deployment.Versions; import java.time.Instant; +import java.time.temporal.ChronoUnit; import java.util.EnumMap; import java.util.Optional; import java.util.SortedMap; @@ -82,6 +83,7 @@ class RunSerializer { private static final String buildField = "build"; private static final String sourceField = "source"; private static final String lastTestRecordField = "lastTestRecord"; + private static final String lastVespaLogTimestampField = "lastVespaLogTimestamp"; private static final String testerCertificateField = "testerCertificate"; Run runFromSlime(Slime slime) { @@ -114,6 +116,7 @@ class RunSerializer { .map(end -> Instant.ofEpochMilli(end.asLong())), runStatusOf(runObject.field(statusField).asString()), runObject.field(lastTestRecordField).asLong(), + Instant.EPOCH.plus(runObject.field(lastVespaLogTimestampField).asLong(), ChronoUnit.MICROS), Optional.of(runObject.field(testerCertificateField)) .filter(Inspector::valid) .map(certificate -> X509CertificateUtils.fromPem(certificate.asString()))); @@ -174,6 +177,7 @@ class RunSerializer { run.end().ifPresent(end -> runObject.setLong(endField, end.toEpochMilli())); runObject.setString(statusField, valueOf(run.status())); runObject.setLong(lastTestRecordField, run.lastTestLogEntry()); + runObject.setLong(lastVespaLogTimestampField, Instant.EPOCH.until(run.lastVespaLogTimestamp(), ChronoUnit.MICROS)); run.testerCertificate().ifPresent(certificate -> runObject.setString(testerCertificateField, X509CertificateUtils.toPem(certificate))); Cursor stepsObject = runObject.setObject(stepsField); diff --git a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/restapi/application/JobControllerApiHandlerHelper.java b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/restapi/application/JobControllerApiHandlerHelper.java index 293f4f9a8e3..9940d5635b1 100644 --- a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/restapi/application/JobControllerApiHandlerHelper.java +++ b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/restapi/application/JobControllerApiHandlerHelper.java @@ -391,6 +391,8 @@ class JobControllerApiHandlerHelper { detailsObject.setBool("active", ! run.hasEnded()); detailsObject.setString("status", nameOf(run.status())); jobController.updateTestLog(runId); + try { jobController.updateVespaLog(runId); } + catch (RuntimeException ignored) { } // May be perfectly fine, e.g., when logserver isn't up yet. RunLog runLog = (after == null ? jobController.details(runId) : jobController.details(runId, Long.parseLong(after))) .orElseThrow(() -> new NotExistsException(String.format( @@ -412,7 +414,7 @@ class JobControllerApiHandlerHelper { } private static void toSlime(Cursor entryObject, LogEntry entry) { - entryObject.setLong("at", entry.at()); + entryObject.setLong("at", entry.at().toEpochMilli()); entryObject.setString("type", entry.type().name()); entryObject.setString("message", entry.message()); } diff --git a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/deployment/BadgesTest.java b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/deployment/BadgesTest.java index 0e5bf774441..1bb3120dd8e 100644 --- a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/deployment/BadgesTest.java +++ b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/deployment/BadgesTest.java @@ -20,6 +20,7 @@ import java.util.Optional; import static com.yahoo.vespa.hosted.controller.api.integration.deployment.JobType.stagingTest; import static com.yahoo.vespa.hosted.controller.api.integration.deployment.JobType.systemTest; import static com.yahoo.vespa.hosted.controller.deployment.Step.report; +import static java.time.Instant.EPOCH; import static java.time.Instant.now; import static org.junit.Assert.assertEquals; import static org.junit.Assert.fail; @@ -31,13 +32,13 @@ public class BadgesTest { private static final ApplicationId id = ApplicationId.from("tenant", "application", "default"); private static final Run success = new Run(new RunId(id, systemTest, 3), ImmutableMap.of(report, Step.Status.succeeded), - null, null, Optional.of(now()), RunStatus.success, 0, Optional.empty()); + null, null, Optional.of(now()), RunStatus.success, 0, EPOCH, Optional.empty()); private static final Run running = new Run(new RunId(id, systemTest, 4), ImmutableMap.of(report, Step.Status.succeeded), - null, null, Optional.empty(), RunStatus.running, 0, Optional.empty()); + null, null, Optional.empty(), RunStatus.running, 0, EPOCH, Optional.empty()); private static final Run failure = new Run(new RunId(id, JobType.stagingTest, 2), ImmutableMap.of(report, Step.Status.succeeded), - null, null, Optional.of(now()), RunStatus.testFailure, 0, Optional.empty()); + null, null, Optional.of(now()), RunStatus.testFailure, 0, EPOCH, Optional.empty()); @Test public void test() { 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 fb850b1b321..55873d5df16 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 @@ -1,6 +1,7 @@ // Copyright 2018 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. package com.yahoo.vespa.hosted.controller.deployment; +import com.google.common.collect.ImmutableList; import com.yahoo.component.Version; import com.yahoo.config.application.api.DeploymentSpec; import com.yahoo.config.provision.AthenzDomain; @@ -36,6 +37,8 @@ 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.Collections; import java.util.List; @@ -268,29 +271,29 @@ public class InternalStepRunnerTest { @Test public void testsFailIfTestsFailRemotely() { RunId id = tester.startSystemTestTests(); - tester.cloud().add(new LogEntry(123, 321, error, "Failure!")); + tester.cloud().add(new LogEntry(123, Instant.ofEpochMilli(321), error, "Failure!")); tester.cloud().set(TesterCloud.Status.FAILURE); long lastId = tester.jobs().details(id).get().lastId().getAsLong(); tester.runner().run(); assertTestLogEntries(id, Step.endTests, - new LogEntry(lastId + 1, 321, error, "Failure!"), - new LogEntry(lastId + 2, tester.clock().millis(), debug, "Tests failed.")); + new LogEntry(lastId + 1, Instant.ofEpochMilli(321), error, "Failure!"), + new LogEntry(lastId + 2, tester.clock().instant(), debug, "Tests failed.")); assertEquals(failed, tester.jobs().run(id).get().steps().get(Step.endTests)); } @Test public void testsFailIfTestsErr() { RunId id = tester.startSystemTestTests(); - tester.cloud().add(new LogEntry(0, 123, error, "Error!")); + tester.cloud().add(new LogEntry(0, Instant.ofEpochMilli(123), error, "Error!")); tester.cloud().set(TesterCloud.Status.ERROR); 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.endTests, - new LogEntry(lastId + 1, 123, error, "Error!"), - new LogEntry(lastId + 2, tester.clock().millis(), info, "Tester failed running its tests!")); + new LogEntry(lastId + 1, Instant.ofEpochMilli(123), error, "Error!"), + new LogEntry(lastId + 2, tester.clock().instant(), info, "Tester failed running its tests!")); } @Test @@ -309,25 +312,25 @@ public class InternalStepRunnerTest { configObject.field("endpoints").field(JobType.systemTest.zone(system()).value()).traverse((ArrayTraverser) (__, endpoint) -> assertEquals(tester.routing().endpoints(new DeploymentId(appId, JobType.systemTest.zone(system()))).get(0).endpoint(), endpoint.asString())); long lastId = tester.jobs().details(id).get().lastId().getAsLong(); - tester.cloud().add(new LogEntry(0, 123, info, "Ready!")); + tester.cloud().add(new LogEntry(0, Instant.ofEpochMilli(123), info, "Ready!")); tester.runner().run(); assertTestLogEntries(id, Step.endTests, - new LogEntry(lastId + 1, 123, info, "Ready!")); + new LogEntry(lastId + 1, Instant.ofEpochMilli(123), info, "Ready!")); - tester.cloud().add(new LogEntry(1, 1234, info, "Steady!")); + tester.cloud().add(new LogEntry(1, Instant.ofEpochMilli(1234), info, "Steady!")); tester.runner().run(); assertTestLogEntries(id, Step.endTests, - new LogEntry(lastId + 1, 123, info, "Ready!"), - new LogEntry(lastId + 2, 1234, info, "Steady!")); + new LogEntry(lastId + 1, Instant.ofEpochMilli(123), info, "Ready!"), + new LogEntry(lastId + 2, Instant.ofEpochMilli(1234), info, "Steady!")); - tester.cloud().add(new LogEntry(12, 12345, info, "Success!")); + tester.cloud().add(new LogEntry(12, Instant.ofEpochMilli(12345), info, "Success!")); tester.cloud().set(TesterCloud.Status.SUCCESS); tester.runner().run(); assertTestLogEntries(id, Step.endTests, - new LogEntry(lastId + 1, 123, info, "Ready!"), - new LogEntry(lastId + 2, 1234, info, "Steady!"), - new LogEntry(lastId + 3, 12345, info, "Success!"), - new LogEntry(lastId + 4, tester.clock().millis(), debug, "Tests completed successfully.")); + new LogEntry(lastId + 1, Instant.ofEpochMilli(123), info, "Ready!"), + new LogEntry(lastId + 2, Instant.ofEpochMilli(1234), info, "Steady!"), + new LogEntry(lastId + 3, Instant.ofEpochMilli(12345), info, "Success!"), + new LogEntry(lastId + 4, tester.clock().instant(), debug, "Tests completed successfully.")); assertEquals(succeeded, tester.jobs().run(id).get().steps().get(Step.endTests)); } @@ -392,20 +395,16 @@ public class InternalStepRunnerTest { 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 test.us-east-1 ..."), - 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, + new LogEntry(lastId + 2, Instant.EPOCH.plus(3554970337935104L, ChronoUnit.MICROS), 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, + new LogEntry(lastId + 3, Instant.EPOCH.plus(3554970337947777L, ChronoUnit.MICROS), 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, + new LogEntry(lastId + 4, Instant.EPOCH.plus(3554970337947820L, ChronoUnit.MICROS), 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, + new LogEntry(lastId + 5, Instant.EPOCH.plus(3554970337947845L, ChronoUnit.MICROS), 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)")); } @@ -426,14 +425,14 @@ public class InternalStepRunnerTest { } private void assertTestLogEntries(RunId id, Step step, LogEntry... entries) { - assertEquals(List.of(entries), tester.jobs().details(id).get().get(step)); + assertEquals(ImmutableList.copyOf(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)"; + 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)"; @Test public void generates_correct_services_xml_test() { diff --git a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/persistence/BufferedLogStoreTest.java b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/persistence/BufferedLogStoreTest.java index a6022d259be..394f884f20f 100644 --- a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/persistence/BufferedLogStoreTest.java +++ b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/persistence/BufferedLogStoreTest.java @@ -11,6 +11,7 @@ import com.yahoo.vespa.hosted.controller.deployment.RunLog; import com.yahoo.vespa.hosted.controller.deployment.Step; import org.junit.Test; +import java.time.Instant; import java.util.Arrays; import java.util.Collections; import java.util.List; @@ -32,7 +33,7 @@ public class BufferedLogStoreTest { byte[] manyBytes = new byte[BufferedLogStore.chunkSize / 2 + 1]; // One fits, and two (over-)fills. Arrays.fill(manyBytes, (byte) 'O'); - LogEntry entry = new LogEntry(0, 123, LogEntry.Type.warning, new String(manyBytes)); + LogEntry entry = new LogEntry(0, Instant.ofEpochMilli(123), LogEntry.Type.warning, new String(manyBytes)); // Log entries are re-sequenced by the log store, by enumeration. LogEntry entry0 = new LogEntry(0, entry.at(), entry.type(), entry.message()); 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 index a53a026eff6..e8029e0bdbd 100644 --- 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 @@ -9,6 +9,7 @@ import java.io.IOException; import java.nio.file.Files; import java.nio.file.Path; import java.nio.file.Paths; +import java.time.Instant; import java.util.ArrayList; import java.util.HashMap; import java.util.List; @@ -33,10 +34,10 @@ public class LogSerializerTest { byte[] logJson = Files.readAllBytes(logsFile); - LogEntry first = new LogEntry(0, 0, LogEntry.Type.info, "First"); - LogEntry second = new LogEntry(1, 0, LogEntry.Type.info, "Second"); - LogEntry third = new LogEntry(2, 1000, LogEntry.Type.debug, "Third"); - LogEntry fourth = new LogEntry(3, 2000, LogEntry.Type.warning, "Fourth"); + LogEntry first = new LogEntry(0, Instant.ofEpochMilli(0), LogEntry.Type.info, "First"); + LogEntry second = new LogEntry(1, Instant.ofEpochMilli(0), LogEntry.Type.info, "Second"); + LogEntry third = new LogEntry(2, Instant.ofEpochMilli(1000), LogEntry.Type.debug, "Third"); + LogEntry fourth = new LogEntry(3, Instant.ofEpochMilli(2000), LogEntry.Type.warning, "Fourth"); Map<Step, List<LogEntry>> expected = new HashMap<>(); expected.put(deployReal, new ArrayList<>()); 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 bf6cf716b7d..f76880c3f7a 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 @@ -20,13 +20,10 @@ import java.nio.file.Files; import java.nio.file.Path; import java.nio.file.Paths; import java.time.Instant; -import java.time.temporal.ChronoUnit; import java.util.Collections; -import java.util.Optional; 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.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; @@ -117,7 +114,10 @@ public class RunSerializerTest { .build(), run.steps()); - run = run.aborted().finished(Instant.now().truncatedTo(MILLIS)); + run = run.with(1L << 50) + .with(Instant.now().truncatedTo(MILLIS)) + .aborted() + .finished(Instant.now().truncatedTo(MILLIS)); assertEquals(aborted, run.status()); assertTrue(run.hasEnded()); 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 e112493cb94..535c87d9a7a 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 @@ -6,6 +6,7 @@ "start": 1196676930000, "status": "running", "lastTestRecord": 3, + "lastVespaLogTimestamp": 1196676930000432, "testerCertificate": "-----BEGIN CERTIFICATE-----\nMIIBEzCBu6ADAgECAgEBMAoGCCqGSM49BAMEMBQxEjAQBgNVBAMTCW15c2Vydmlj\nZTAeFw0xOTA5MDYwNzM3MDZaFw0xOTA5MDcwNzM3MDZaMBQxEjAQBgNVBAMTCW15\nc2VydmljZTBZMBMGByqGSM49AgEGCCqGSM49AwEHA0IABM0JhD8fV2DlAkjQOGX3\nY50ryMBr3g2+v/uFiRoxJ1muuSOWYrW7HCQIGuzc04fa0QwtaX/voAZKCV51t6jF\n0fwwCgYIKoZIzj0EAwQDRwAwRAIgVbQ3Co1H4X0gmRrtXSyTU0HgBQu9PXHMmX20\n5MyyPSoCIBltOcmaPfdN03L3zqbqZ6PgUBWsvAHgiBzL3hrtJ+iy\n-----END CERTIFICATE-----", "steps": { "deployInitialReal": "unfinished", 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 614df953ca9..043ce712636 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 @@ -26,6 +26,7 @@ import java.util.Optional; import static com.yahoo.vespa.hosted.controller.api.integration.configserver.ConfigServerException.ErrorCode.INVALID_APPLICATION_PACKAGE; import static com.yahoo.vespa.hosted.controller.api.integration.deployment.JobType.devAwsUsEast2a; +import static com.yahoo.vespa.hosted.controller.api.integration.deployment.JobType.devUsEast1; import static com.yahoo.vespa.hosted.controller.api.integration.deployment.JobType.productionUsCentral1; import static com.yahoo.vespa.hosted.controller.api.integration.deployment.JobType.productionUsEast3; import static com.yahoo.vespa.hosted.controller.api.integration.deployment.JobType.productionUsWest1; @@ -129,11 +130,16 @@ public class JobControllerApiHandlerHelperTest { ZoneId zone = JobType.devUsEast1.zone(tester.tester().controller().system()); tester.jobs().deploy(appId, JobType.devUsEast1, Optional.empty(), applicationPackage); + tester.configServer().setLogStream("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"); + assertResponse(JobControllerApiHandlerHelper.runDetailsResponse(tester.jobs(), tester.jobs().last(appId, devUsEast1).get().id(), null), "dev-us-east-1-log-first-part.json"); + + tester.configServer().setLogStream("Nope, this won't be logged"); tester.configServer().convergeServices(appId, zone); tester.setEndpoints(appId, zone); tester.runner().run(); assertResponse(JobControllerApiHandlerHelper.jobTypeResponse(tester.tester().controller(), appId, URI.create("https://some.url:43/root")), "dev-overview.json"); + assertResponse(JobControllerApiHandlerHelper.runDetailsResponse(tester.jobs(), tester.jobs().last(appId, devUsEast1).get().id(), "9"), "dev-us-east-1-log-second-part.json"); } @Test diff --git a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/dev-aws-us-east-2a-runs.json b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/dev-aws-us-east-2a-runs.json index 82bdc4ca195..fe90ddd772e 100644 --- a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/dev-aws-us-east-2a-runs.json +++ b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/dev-aws-us-east-2a-runs.json @@ -10,7 +10,8 @@ }, "steps": { "deployReal": "succeeded", - "installReal": "succeeded" + "installReal": "succeeded", + "copyVespaLogs": "succeeded" }, "tasks": { "deploy": "succeeded", diff --git a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/dev-overview.json b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/dev-overview.json index 88bf5300ec2..bfaa62a602d 100644 --- a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/dev-overview.json +++ b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/dev-overview.json @@ -17,7 +17,8 @@ }, "steps": { "deployReal": "succeeded", - "installReal": "succeeded" + "installReal": "succeeded", + "copyVespaLogs": "succeeded" }, "tasks": { "deploy": "succeeded", diff --git a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/dev-us-east-1-log-first-part.json b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/dev-us-east-1-log-first-part.json new file mode 100644 index 00000000000..5cd1afa3fb9 --- /dev/null +++ b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/dev-us-east-1-log-first-part.json @@ -0,0 +1,63 @@ +{ + "log": { + "deployReal": [ + { + "at": 0, + "type": "debug", + "message": "Deploying platform version 6.1 and application version unknown ..." + }, + { + "at": 0, + "type": "debug", + "message": "No services requiring restart." + }, + { + "at": 0, + "type": "debug", + "message": "Deployment successful." + }, + { + "at": 0, + "type": "debug", + "message": "foo" + } + ], + "installReal": [ + { + "at": 0, + "type": "debug", + "message": "Checking installation of 6.1 and unknown ..." + }, + { + "at": 0, + "type": "debug", + "message": " host-tenant:application:default-dev.us-east-1: unorchestrated 6.1 " + }, + { + "at": 0, + "type": "debug", + "message": "Wanted config generation is 2" + }, + { + "at": 0, + "type": "debug", + "message": " host-tenant:application:default-dev.us-east-1: container on port 43 has config generation 1" + }, + { + "at": 0, + "type": "debug", + "message": "Installation not yet complete." + } + ], + "copyVespaLogs": [ + { + "at": 1554970337935, + "type": "info", + "message": "17491290-v6-1.ostk.bm2.prod.ne1.yahoo.com\tcontainer\tstdout\nERROR: Bundle canary-application [71] Unable to get module class path. (java.lang.NullPointerException)" + } + ] + }, + "active": true, + "lastId": 9, + "status": "running" +} diff --git a/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/dev-us-east-1-log-second-part.json b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/dev-us-east-1-log-second-part.json new file mode 100644 index 00000000000..57b3f382c76 --- /dev/null +++ b/controller-server/src/test/java/com/yahoo/vespa/hosted/controller/restapi/application/responses/dev-us-east-1-log-second-part.json @@ -0,0 +1,54 @@ +{ + "log": { + "installReal": [ + { + "at": 0, + "type": "debug", + "message": "Checking installation of 6.1 and unknown ..." + }, + { + "at": 0, + "type": "debug", + "message": " host-tenant:application:default-dev.us-east-1: unorchestrated 6.1 " + }, + { + "at": 0, + "type": "debug", + "message": "Wanted config generation is 2" + }, + { + "at": 0, + "type": "debug", + "message": "All services on wanted config generation." + }, + { + "at": 0, + "type": "debug", + "message": "Attempting to find deployment endpoints ..." + }, + { + "at": 0, + "type": "debug", + "message": "Found endpoints:" + }, + { + "at": 0, + "type": "debug", + "message": "- dev.us-east-1" + }, + { + "at": 0, + "type": "debug", + "message": " |-- https://default--application--tenant.us-east-1.dev.vespa:43 (cluster 'default')" + }, + { + "at": 0, + "type": "debug", + "message": "Installation succeeded!" + } + ] + }, + "active": false, + "lastId": 18, + "status": "success" +} 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 222cf88ed87..8c92288f88c 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 @@ -140,7 +140,8 @@ }, "steps": { "deployReal": "unfinished", - "installReal": "unfinished" + "installReal": "unfinished", + "copyVespaLogs": "unfinished" }, "tasks": {}, "log": "http://localhost:8080/application/v4/tenant/tenant1/application/application1/instance/instance1/job/dev-us-east-1/run/1" |