fix(monitored deploy): log everything better (#3180)

This change cleans up and significantly improves logging for deployment monitors.
Additionally, it take advantage of the dynamic task timeout mechanism newly minted in orca (see #3159)

The following will be added to context for `deck` to parse and present to user:
* The current status the deployment monitor has provided (e.g. wait/continue/abort)
* In case of failures to communicate with the deployment monitor
* A better high level summary of response from deployment monitor

The following simple logging is improved:
* retrofit errors

orca-clouddriver/src/main/groovy/com/netflix/spinnaker/orca/clouddriver/tasks/monitoreddeploy/EvaluateDeploymentHealthTask.java

@@ -23,11 +23,7 @@
 import com.netflix.spinnaker.orca.TaskResult;
 import com.netflix.spinnaker.orca.deploymentmonitor.models.EvaluateHealthRequest;
 import com.netflix.spinnaker.orca.deploymentmonitor.models.EvaluateHealthResponse;
-import com.netflix.spinnaker.orca.deploymentmonitor.models.StatusReason;
 import java.time.Instant;
-import java.util.Collections;
-import java.util.List;
-import java.util.Optional;
 import java.util.concurrent.TimeUnit;
 import javax.annotation.Nonnull;
 import org.springframework.beans.factory.annotation.Autowired;
@@ -77,10 +73,7 @@ public class EvaluateDeploymentHealthTask extends MonitoredDeployBaseTask {
       registry.timer(timerId).record(duration, TimeUnit.MILLISECONDS);
     }
 
-    List<StatusReason> statusReasons =
-        Optional.ofNullable(response.getStatusReasons()).orElse(Collections.emptyList());
-
-    return processDirective(directive).context("deploymentMonitorReasons", statusReasons).build();
+    return buildTaskResult(processDirective(directive), response);
   }
 
   private TaskResult.TaskResultBuilder processDirective(

orca-clouddriver/src/main/groovy/com/netflix/spinnaker/orca/clouddriver/tasks/monitoreddeploy/MonitoredDeployBaseTask.java

@@ -16,6 +16,7 @@
 
 package com.netflix.spinnaker.orca.clouddriver.tasks.monitoreddeploy;
 
+import com.google.common.io.CharStreams;
 import com.netflix.spectator.api.Registry;
 import com.netflix.spinnaker.config.DeploymentMonitorDefinition;
 import com.netflix.spinnaker.config.DeploymentMonitorServiceProvider;
@@ -25,12 +26,24 @@
 import com.netflix.spinnaker.orca.clouddriver.pipeline.servergroup.strategies.MonitoredDeployStageData;
 import com.netflix.spinnaker.orca.deploymentmonitor.models.DeploymentStep;
 import com.netflix.spinnaker.orca.deploymentmonitor.models.EvaluateHealthResponse;
+import com.netflix.spinnaker.orca.deploymentmonitor.models.StatusExplanation;
+import com.netflix.spinnaker.orca.deploymentmonitor.models.StatusReason;
 import com.netflix.spinnaker.orca.pipeline.model.Stage;
+import java.io.InputStreamReader;
+import java.nio.charset.StandardCharsets;
+import java.time.Duration;
+import java.util.Collections;
+import java.util.List;
+import java.util.Optional;
 import java.util.concurrent.TimeUnit;
+import java.util.stream.Collectors;
 import javax.annotation.Nonnull;
+import javax.annotation.Nullable;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 import retrofit.RetrofitError;
+import retrofit.client.Header;
+import retrofit.client.Response;
 
 public class MonitoredDeployBaseTask implements RetryableTask {
   private static final int MAX_RETRY_COUNT = 3;
@@ -54,22 +67,66 @@ public long getBackoffPeriod() {
 
   @Override
   public long getTimeout() {
-    // TODO(mvulfson): Use DeploymentMonitorDefinition
-    return TimeUnit.MINUTES.toMillis(30);
+    // NOTE: This is not used since we override getDynamicTimeout
+    return 0;
+  }
+
+  @Override
+  public long getDynamicTimeout(Stage stage) {
+    ensureMonitorDefinition(stage);
+
+    final Duration defaultTimeout = Duration.ofMinutes(60);
+    long timeout;
+
+    try {
+      timeout = TimeUnit.MINUTES.toMillis(monitorDefinition.getMaxAnalysisMinutes());
+    } catch (Exception e) {
+      log.error(
+          "Failed to compute timeout for {}, returning {} min",
+          getClass().getSimpleName(),
+          defaultTimeout.toMinutes(),
+          e);
+
+      timeout = defaultTimeout.toMillis();
+    }
+
+    return timeout;
+  }
+
+  @Override
+  public @Nullable TaskResult onTimeout(@Nonnull Stage stage) {
+    ensureMonitorDefinition(stage);
+
+    ExecutionStatus taskStatus;
+    String message;
+
+    if (monitorDefinition.isFailOnError()) {
+      message =
+          "Deployment monitor failed to evaluate health in the allotted time, assuming failure because the monitor is configured to failOnError";
+      taskStatus = ExecutionStatus.TERMINAL;
+    } else {
+      message =
+          "Deployment monitor failed to evaluate health in the allotted time, proceeding anyway because the monitor is not configured to failOnError";
+      taskStatus = ExecutionStatus.FAILED_CONTINUE;
+    }
+
+    return buildTaskResult(TaskResult.builder(taskStatus), message);
   }
 
   @Override
   public @Nonnull TaskResult execute(@Nonnull Stage stage) {
     MonitoredDeployStageData context = stage.mapTo(MonitoredDeployStageData.class);
 
     try {
-      this.stage = stage;
-      this.monitorDefinition =
-          deploymentMonitorServiceProvider.getDefinitionById(
-              context.getDeploymentMonitor().getId());
-
+      ensureMonitorDefinition(stage);
       return executeInternal();
     } catch (RetrofitError e) {
+      log.warn(
+          "HTTP Error encountered while talking to {}->{}, {}}",
+          monitorDefinition,
+          e.getUrl(),
+          getRetrofitLogMessage(e.getResponse()),
+          e);
 
       return handleError(context, e, true);
     } catch (DeploymentMonitorInvalidDataException e) {
@@ -120,10 +177,12 @@ private TaskResult handleError(
           monitorDefinition,
           e);
 
-      return TaskResult.builder(ExecutionStatus.TERMINAL)
-          // TODO(mvulfson)
-          // .context()
-          .build();
+      String userMessage =
+          String.format(
+              "Failed to get a valid response from deployment monitor %s, aborting because this deployment monitor is configured to failOnError",
+              monitorDefinition.getName());
+
+      return buildTaskResult(TaskResult.builder(ExecutionStatus.TERMINAL), userMessage);
     }
 
     log.warn(
@@ -132,10 +191,63 @@ private TaskResult handleError(
         monitorDefinition,
         e);
 
-    return TaskResult.builder(ExecutionStatus.SUCCEEDED)
-        // TODO(mvulfson)
-        // .context()
-        .build();
+    String userMessage =
+        String.format(
+            "Failed to get a valid response from deployment monitor %s, proceeding anyway because this deployment monitor is configured to not failOnError",
+            monitorDefinition.getName());
+
+    return buildTaskResult(TaskResult.builder(ExecutionStatus.SUCCEEDED), userMessage);
+  }
+
+  private void ensureMonitorDefinition(Stage stage) {
+    if (this.stage == null) {
+      MonitoredDeployStageData context = stage.mapTo(MonitoredDeployStageData.class);
+      this.stage = stage;
+      this.monitorDefinition =
+          deploymentMonitorServiceProvider.getDefinitionById(
+              context.getDeploymentMonitor().getId());
+    }
+  }
+
+  TaskResult buildTaskResult(
+      TaskResult.TaskResultBuilder taskResultBuilder, EvaluateHealthResponse response) {
+    List<StatusReason> statusReasons =
+        Optional.ofNullable(response.getStatusReasons()).orElse(Collections.emptyList());
+
+    String summary = "Deployment monitor requested to: " + response.getNextStep().getDirective();
+    StatusExplanation explanation = new StatusExplanation(summary, statusReasons);
+
+    return taskResultBuilder.context("deploymentMonitorReasons", explanation).build();
+  }
+
+  TaskResult buildTaskResult(TaskResult.TaskResultBuilder taskResultBuilder, String summary) {
+    StatusExplanation explanation = new StatusExplanation(summary);
+
+    return taskResultBuilder.context("deploymentMonitorReasons", explanation).build();
+  }
+
+  private String getRetrofitLogMessage(Response response) {
+    if (response == null) {
+      return "<NO RESPONSE>";
+    }
+
+    String body = "";
+    String status = "";
+    String headers = "";
+
+    try {
+      status = String.format("%d (%s)", response.getStatus(), response.getReason());
+      body =
+          CharStreams.toString(
+              new InputStreamReader(response.getBody().in(), StandardCharsets.UTF_8));
+      headers =
+          response.getHeaders().stream().map(Header::toString).collect(Collectors.joining("\n"));
+    } catch (Exception e) {
+      log.error(
+          "Failed to fully parse retrofit error while reading response from deployment monitor", e);
+    }
+
+    return String.format("status: %s\nheaders: %s\nresponse body: %s", status, headers, body);
   }
 
   void sanitizeAndLogResponse(EvaluateHealthResponse response) {

orca-clouddriver/src/main/groovy/com/netflix/spinnaker/orca/clouddriver/tasks/monitoreddeploy/NotifyDeployStartingTask.java

@@ -22,10 +22,6 @@
 import com.netflix.spinnaker.orca.TaskResult;
 import com.netflix.spinnaker.orca.deploymentmonitor.models.EvaluateHealthResponse;
 import com.netflix.spinnaker.orca.deploymentmonitor.models.RequestBase;
-import com.netflix.spinnaker.orca.deploymentmonitor.models.StatusReason;
-import java.util.Collections;
-import java.util.List;
-import java.util.Optional;
 import javax.annotation.Nonnull;
 import org.springframework.beans.factory.annotation.Autowired;
 import org.springframework.boot.autoconfigure.condition.ConditionalOnProperty;
@@ -47,12 +43,7 @@ public class NotifyDeployStartingTask extends MonitoredDeployBaseTask {
 
     sanitizeAndLogResponse(response);
 
-    List<StatusReason> statusReasons =
-        Optional.ofNullable(response.getStatusReasons()).orElse(Collections.emptyList());
-
-    return processDirective(response.getNextStep().getDirective())
-        .context("deploymentMonitorReasons", statusReasons)
-        .build();
+    return buildTaskResult(processDirective(response.getNextStep().getDirective()), response);
   }
 
   private TaskResult.TaskResultBuilder processDirective(

orca-deploymentmonitor/src/main/java/com/netflix/spinnaker/config/DeploymentMonitorConfiguration.java

@@ -21,6 +21,7 @@
 import org.springframework.context.annotation.Bean;
 import org.springframework.context.annotation.Configuration;
 import retrofit.RequestInterceptor;
+import retrofit.RestAdapter;
 import retrofit.client.Client;
 
 @Configuration
@@ -31,8 +32,12 @@ public class DeploymentMonitorConfiguration {
   DeploymentMonitorServiceProvider deploymentMonitorServiceProvider(
       MonitoredDeployConfigurationProperties config,
       Client retrofitClient,
+      RestAdapter.LogLevel retrofitLogLevel,
       RequestInterceptor spinnakerRequestInterceptor) {
     return new DeploymentMonitorServiceProvider(
-        retrofitClient, spinnakerRequestInterceptor, config.getDeploymentMonitors());
+        retrofitClient,
+        retrofitLogLevel,
+        spinnakerRequestInterceptor,
+        config.getDeploymentMonitors());
   }
 }

orca-deploymentmonitor/src/main/java/com/netflix/spinnaker/config/DeploymentMonitorDefinition.java

@@ -30,6 +30,9 @@ public class DeploymentMonitorDefinition {
   /** Base URL for this deployment monitor */
   private String baseUrl;
 
+  /** Contact/support information link */
+  private String supportContact;
+
   /**
    * Maximum number of minutes this deployment monitor is allowed to respond to the /evaluateHealth
    * request. Failure to respond in this time frame will result in deployment failure.

orca-deploymentmonitor/src/main/java/com/netflix/spinnaker/config/DeploymentMonitorServiceProvider.java

@@ -33,15 +33,18 @@ public class DeploymentMonitorServiceProvider {
   private static final Logger log = LoggerFactory.getLogger(DeploymentMonitorServiceProvider.class);
 
   private Client retrofitClient;
+  private RestAdapter.LogLevel retrofitLogLevel;
   private RequestInterceptor spinnakerRequestInterceptor;
   private List<DeploymentMonitorDefinition> deploymentMonitors;
   private HashMap<String, DeploymentMonitorService> serviceCache;
 
   public DeploymentMonitorServiceProvider(
       Client retrofitClient,
+      RestAdapter.LogLevel retrofitLogLevel,
       RequestInterceptor spinnakerRequestInterceptor,
       List<DeploymentMonitorDefinition> deploymentMonitors) {
     this.retrofitClient = retrofitClient;
+    this.retrofitLogLevel = retrofitLogLevel;
     this.spinnakerRequestInterceptor = spinnakerRequestInterceptor;
     this.deploymentMonitors = deploymentMonitors;
     this.serviceCache = new HashMap<>();
@@ -75,8 +78,7 @@ private synchronized DeploymentMonitorService getServiceByDefinition(
               .setRequestInterceptor(spinnakerRequestInterceptor)
               .setEndpoint(definition.getBaseUrl())
               .setClient(retrofitClient)
-              // TODO(mvulfson): Change logging level
-              .setLogLevel(RestAdapter.LogLevel.HEADERS_AND_ARGS)
+              .setLogLevel(retrofitLogLevel)
               .setLog(new RetrofitSlf4jLog(DeploymentMonitorService.class))
               .setConverter(new JacksonConverter())
               .build()

orca-deploymentmonitor/src/main/java/com/netflix/spinnaker/orca/deploymentmonitor/models/StatusExplanation.java

@@ -0,0 +1,36 @@
+/*
+ * Copyright 2019 Netflix, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package com.netflix.spinnaker.orca.deploymentmonitor.models;
+
+import java.util.Collections;
+import java.util.List;
+import lombok.Data;
+
+@Data
+public class StatusExplanation {
+  private String summary;
+  private List<StatusReason> reasons;
+
+  public StatusExplanation(String summary) {
+    this(summary, Collections.emptyList());
+  }
+
+  public StatusExplanation(String summary, List<StatusReason> reasons) {
+    this.summary = summary;
+    this.reasons = reasons;
+  }
+}

orca-web/src/main/groovy/com/netflix/spinnaker/orca/model/DeploymentMonitorDefinition.java

@@ -22,12 +22,14 @@
 public class DeploymentMonitorDefinition {
   private String id;
   private String name;
+  private String supportContact;
 
   public DeploymentMonitorDefinition() {}
 
   public DeploymentMonitorDefinition(
       com.netflix.spinnaker.config.DeploymentMonitorDefinition definition) {
     id = definition.getId();
     name = definition.getName();
+    supportContact = definition.getSupportContact();
   }
 }