Merge pull request #173 from spotify/rculbertson/clean-temp-job-logs

Improve log messages from helios testing framework

Author: rculbertson

helios-testing/src/main/java/com/spotify/helios/testing/Jobs.java

@@ -24,10 +24,14 @@
 import com.google.common.util.concurrent.ListenableFuture;
 
 import com.spotify.helios.client.HeliosClient;
+import com.spotify.helios.common.descriptors.Job;
 import com.spotify.helios.common.descriptors.JobId;
 import com.spotify.helios.common.protocol.JobDeleteResponse;
 import com.spotify.helios.common.protocol.JobUndeployResponse;
 
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
 import java.util.List;
 import java.util.concurrent.ExecutionException;
 import java.util.concurrent.TimeUnit;
@@ -38,6 +42,8 @@
 
 class Jobs {
 
+  private static final Logger log = LoggerFactory.getLogger(Jobs.class);
+
   static final long TIMEOUT_MILLIS = TimeUnit.MINUTES.toMillis(5);
 
   static <T> T get(final ListenableFuture<T> future)
@@ -50,39 +56,47 @@ static <T> T get(final ListenableFuture<T> future, final long timeout)
     return future.get(timeout, MILLISECONDS);
   }
 
+  static String getJobDescription(final Job job) {
+    final String shortHash = job.getId().getHash().substring(0, 7);
+    return String.format("%s (Job %s)", job.getImage(), shortHash);
+  }
+
   /**
    * Undeploy the job from all specified hosts, and delete the job. Any failures will be ignored,
    * and we will keep trying each host. A list of errors encountered along the way will be returned
    * to the caller.
    * @param client the HeliosClient to use
-   * @param jobId the JobId to undeploy and delete
+   * @param job the job to undeploy and delete
    * @param hosts the hosts to undeploy from
    * @param errors errors encountered during the undeploy will be added to this list
    * @return the list of errors
    */
-  static List<AssertionError> undeploy(final HeliosClient client, final JobId jobId,
+  static List<AssertionError> undeploy(final HeliosClient client, final Job job,
                                               final List<String> hosts,
                                               final List<AssertionError> errors) {
+    final JobId id = job.getId();
     for (String host : hosts) {
+      log.info("Undeploying {} from {}", getJobDescription(job), host);
       final JobUndeployResponse response;
       try {
-        response = get(client.undeploy(jobId, host));
+        response = get(client.undeploy(id, host));
         if (response.getStatus() != JobUndeployResponse.Status.OK &&
             response.getStatus() != JobUndeployResponse.Status.JOB_NOT_FOUND) {
           errors.add(new AssertionError(format("Failed to undeploy job %s - %s",
-                                               jobId, response)));
+                                               id, response)));
         }
       } catch (InterruptedException | ExecutionException | TimeoutException e) {
         errors.add(new AssertionError(e));
       }
     }
 
     try {
-      final JobDeleteResponse response = get(client.deleteJob(jobId));
+      log.debug("Deleting job {}", id);
+      final JobDeleteResponse response = get(client.deleteJob(id));
       if (response.getStatus() != JobDeleteResponse.Status.OK &&
           response.getStatus() != JobDeleteResponse.Status.JOB_NOT_FOUND) {
         errors.add(new AssertionError(format("Failed to delete job %s - %s",
-                                             jobId.toString(), response.toString())));
+                                             id.toString(), response.toString())));
       }
     } catch (InterruptedException | ExecutionException | TimeoutException e) {
       errors.add(new AssertionError(e));

helios-testing/src/main/java/com/spotify/helios/testing/TemporaryJob.java

@@ -54,6 +54,7 @@
 import static com.google.common.collect.Maps.newHashMap;
 import static com.spotify.helios.testing.Jobs.TIMEOUT_MILLIS;
 import static com.spotify.helios.testing.Jobs.get;
+import static com.spotify.helios.testing.Jobs.getJobDescription;
 import static java.lang.String.format;
 import static java.util.concurrent.TimeUnit.MILLISECONDS;
 import static org.junit.Assert.fail;
@@ -148,9 +149,8 @@ public List<HostAndPort> addresses(final String port) {
 
   void deploy() {
     try {
-      log.info("Deploying job {} with image {}", job.getId(), job.getImage());
-
       // Create job
+      log.info("Creating job {}", job.getId().toShortString());
       final CreateJobResponse createResponse = get(client.createJob(job));
       if (createResponse.getStatus() != CreateJobResponse.Status.OK) {
         fail(format("Failed to create job %s - %s", job.getId(),
@@ -170,7 +170,7 @@ void deploy() {
           hostToIp.put(host, hostAddress);
         }
 
-        log.info("Waiting for Helios job deploy of {} on host {}", deployment.getJobId(), host);
+        log.info("Deploying {} to {}", getJobDescription(job), host);
         final JobDeployResponse deployResponse = get(client.deploy(deployment, host));
         if (deployResponse.getStatus() != JobDeployResponse.Status.OK) {
           fail(format("Failed to deploy job %s %s - %s",
@@ -189,32 +189,30 @@ void deploy() {
   }
 
   void undeploy(final List<AssertionError> errors) {
-    log.info("Undeploying job {}", job.getId());
-
-    Jobs.undeploy(client, job.getId(), hosts, errors);
+    Jobs.undeploy(client, job, hosts, errors);
   }
 
   private void awaitUp(final String host) throws TimeoutException {
-    log.info("Waiting for job {} to be up on host {}", job.getId(), host);
 
     final TaskStatus status = Polling.awaitUnchecked(
         TIMEOUT_MILLIS, MILLISECONDS, new Callable<TaskStatus>() {
           @Override
           public TaskStatus call() throws Exception {
-            log.debug("Getting job status for job {}", job.getId());
-
             final JobStatus status = Futures.getUnchecked(client.jobStatus(job.getId()));
             if (status == null) {
+              log.debug("Job status not available");
               return null;
             }
             final TaskStatus taskStatus = status.getTaskStatuses().get(host);
             if (taskStatus == null) {
+              log.debug("Task status not available on {}", host);
               return null;
             }
 
             verifyHealthy(host, taskStatus);
 
             final TaskStatus.State state = taskStatus.getState();
+            log.info("Job state: {}", state);
 
             if (state == TaskStatus.State.RUNNING) {
               return taskStatus;
@@ -233,7 +231,7 @@ public TaskStatus call() throws Exception {
   }
 
   void verifyHealthy() throws AssertionError {
-    log.debug("Checking health of {}", job.getId());
+    log.debug("Checking health of {}", job.getImage());
     final JobStatus status = Futures.getUnchecked(client.jobStatus(job.getId()));
     if (status == null) {
       return;
@@ -244,7 +242,7 @@ void verifyHealthy() throws AssertionError {
   }
 
   private void verifyHealthy(final String host, final TaskStatus status) {
-    log.debug("Checking health of {} on {}", job.getId(), host);
+    log.debug("Checking health of {} on {}", job.getImage(), host);
     final TaskStatus.State state = status.getState();
     if (state == TaskStatus.State.FAILED ||
         state == TaskStatus.State.EXITED ||
@@ -256,15 +254,11 @@ private void verifyHealthy(final String host, final TaskStatus status) {
       }
       throw new AssertionError(format(
           "Unexpected job state %s. Check helios agent logs for details.", stateString));
-    } else if (state == TaskStatus.State.PULLING_IMAGE) {
-        log.info("Pulling image for {} on {}", job.getId(), host);
     }
   }
 
   private void awaitPort(final String port, final String host) throws TimeoutException {
     final String endpoint = endpointFromHost(host);
-    log.info("Awaiting port availability on {}:{}", endpoint, port);
-
     final TaskStatus taskStatus = statuses.get(host);
     assert taskStatus != null;
     final Integer externalPort = taskStatus.getPorts().get(port).getExternalPort();

helios-testing/src/main/java/com/spotify/helios/testing/TemporaryJobs.java

@@ -21,7 +21,6 @@
 
 package com.spotify.helios.testing;
 
-import com.google.common.base.Joiner;
 import com.google.common.base.Optional;
 import com.google.common.base.Splitter;
 import com.google.common.base.Throwables;
@@ -90,7 +89,7 @@ public class TemporaryJobs implements TestRule {
   private final ExecutorService executor = MoreExecutors.getExitingExecutorService(
       (ThreadPoolExecutor) Executors.newFixedThreadPool(
           1, new ThreadFactoryBuilder()
-              .setNameFormat("helios-temporary-jobs-test-runner-%d")
+              .setNameFormat("helios-test-runner-%d")
               .setDaemon(true)
               .build()),
       0, SECONDS);
@@ -106,8 +105,7 @@ public TemporaryJob deploy(final Job job, final String hostFilter,
 
       final List<String> hosts;
       try {
-        log.info("Getting list of hosts");
-
+        log.debug("Getting list of hosts");
         hosts = client.listHosts().get();
       } catch (InterruptedException | ExecutionException e) {
         throw new AssertionError("Failed to get list of Helios hosts", e);
@@ -138,7 +136,6 @@ public TemporaryJob deploy(final Job job, final List<String> hosts,
              "no arguments to automatically select a host");
       }
 
-      log.info("Deploying {} to {}", job.getImage(), Joiner.on(", ").skipNulls().join(hosts));
       final TemporaryJob temporaryJob = new TemporaryJob(client, prober, job, hosts, waitPorts);
       jobs.add(temporaryJob);
       temporaryJob.deploy();
@@ -190,8 +187,6 @@ public void after() {
 
     final List<AssertionError> errors = newArrayList();
 
-    log.info("Undeploying temporary jobs");
-
     for (TemporaryJob job : jobs) {
       job.undeploy(errors);
     }
@@ -318,7 +313,7 @@ private void verifyJobsHealthy() throws AssertionError {
   private void removeOldJobs(final Path prefixDirectory)
       throws ExecutionException, InterruptedException, IOException {
     final File[] files = prefixDirectory.toFile().listFiles();
-    if (files == null) {
+    if (files == null || files.length == 0) {
       return;
     }
 
@@ -352,16 +347,10 @@ private void removeOldJobs(final Path prefixDirectory)
             continue;
           }
           // Get list of all hosts where this job is deployed, and undeploy
-          log.info("Getting status for job {}", jobId);
           final JobStatus status = client.jobStatus(entry.getKey()).get();
           final List<String> hosts = ImmutableList.copyOf(status.getDeployments().keySet());
-
-          log.info("Undeploying job {} from hosts {}",
-                   jobId,
-                   Joiner.on(", ").skipNulls().join(hosts));
-
           final List<AssertionError> errors =
-              undeploy(client, jobId, hosts, new ArrayList<AssertionError>());
+              undeploy(client, entry.getValue(), hosts, new ArrayList<AssertionError>());
 
           // Set flag indicating if any errors occur
           if (!errors.isEmpty()) {

helios-testing/src/test/java/com/spotify/helios/testing/TemporaryJobsTest.java

@@ -42,14 +42,18 @@
 import static com.google.common.base.Charsets.UTF_8;
 import static com.google.common.collect.Iterables.getOnlyElement;
 import static com.spotify.helios.common.descriptors.HostStatus.Status.UP;
+import static com.spotify.helios.testing.Jobs.getJobDescription;
 import static java.util.concurrent.TimeUnit.MINUTES;
 import static java.util.concurrent.TimeUnit.SECONDS;
+import static org.hamcrest.Matchers.both;
 import static org.hamcrest.Matchers.contains;
+import static org.hamcrest.Matchers.containsString;
 import static org.hamcrest.Matchers.equalTo;
 import static org.hamcrest.Matchers.hasKey;
 import static org.hamcrest.Matchers.is;
 import static org.hamcrest.Matchers.not;
 import static org.hamcrest.Matchers.notNullValue;
+import static org.hamcrest.Matchers.startsWith;
 import static org.junit.Assert.assertArrayEquals;
 import static org.junit.Assert.assertEquals;
 import static org.junit.Assert.assertFalse;
@@ -398,6 +402,20 @@ public void testDeploymentFailure() throws Exception {
     assertTrue("Test should not time out", (end-start) < Jobs.TIMEOUT_MILLIS);
   }
 
+  @Test
+  public void testGetJobDescription() {
+    final Job job = Job.newBuilder()
+        .setImage(BUSYBOX)
+        .setName("testGetJobDescription")
+        .setVersion("1")
+        .build();
+    final String shortHash = job.getId().getHash().substring(0, 7);
+
+    // Simple test to verify the job description contains the image name and a shortened job hash.
+    assertThat(getJobDescription(job),
+               both(startsWith(BUSYBOX)).and(containsString(shortHash)));
+  }
+
   private static boolean fileExists(final Path path, final String prefix) {
     return new File(path.toFile(), prefix).exists();
   }