refactor(deploymentmonitor): use SpinnakerRetrofitErrorHandler with D…

…eploymentMonitorService (#4628)

* refactor(clouddriver/test): configure logback to log messages

to make it possible to add tests that assert on the contents of log messages.

orca-test has a logback-test.xml file that disables logging, so add one for
orca-clouddriver that takes precedence so log messages actually get generated.

Now that logging is enabled, clock.millis() is called an additional time during a test in
ServerGroupCacheForceRefreshTaskSpec.

* test(clouddriver): demonstrate behavior of EvaluateDeploymentHealthTask

to see what changes when moving to SpinnakerRetrofitErrorHandler.  Specifically, these
tests verify the contents of a log message that's tightly coupled to RetrofitError.

* Revert "test(MonitoredDeployBaseTask): Add tests to verify log message for different types of RetrofitError (#4608)"

This reverts commit adc81ac.

With the addition of EvaluateDeploymentHealthTaskTest, we have equivalent coverage that:

- is in java instead of groovy
- doesn't increase the visibility of getRetrofitLogMessage
- more easily shows behavior changes when adopting SpinnakerRetrofitErrorHandler
- is less likely to change when moving from retrofit to retrofit2

* refactor(deploymentmonitor): use SpinnakerRetrofitErrorHandler with DeploymentMonitorService

Note, there's a behavior change here when http response bodies aren't json objects.
Previously, the log message would, barring an exception processing the response, include
the http response body in the log message.  With SpinnakerHttpException, response bodies
that aren't json objects aren't available, so the body appears to be empty.

For example, before:

2024-01-04 12:31:59.640  WARN   --- [    Test worker] n.s.o.c.t.m.EvaluateDeploymentHealthTask : [] HTTP Error encountered while talking to monitorName(monitorId)->http://localhost:49179/deployment/evaluateHealth, status: 400 (Bad Request)
response body: non-json response}
retrofit.RetrofitError: 400 Bad Request
	at retrofit.RetrofitError.httpError(RetrofitError.java:40)

after:

2024-01-04 14:26:13.270  WARN   --- [    Test worker] n.s.o.c.t.m.EvaluateDeploymentHealthTask : [] HTTP Error encountered while talking to monitorName(monitorId)->http://localhost:58192/deployment/evaluateHealth, status: 400 (Bad Request)
response body: }
com.netflix.spinnaker.kork.retrofit.exceptions.SpinnakerHttpException: Status: 400, URL: http://localhost:58192/deployment/evaluateHealth, Message: Bad Request
	at com.netflix.spinnaker.kork.retrofit.exceptions.SpinnakerRetrofitErrorHandler.handleError(SpinnakerRetrofitErrorHandler.java:55)

There's also a behavior change for ConversionException.

before:

2024-01-04 16:03:19.363  WARN   --- [    Test worker] n.s.o.c.t.m.EvaluateDeploymentHealthTask : [] HTTP Error encountered while talking to monitorName(monitorId)->http://localhost:60051/deployment/evaluateHealth, status: 200 (OK)
headers:
response body: }
retrofit.RetrofitError: com.fasterxml.jackson.databind.exc.MismatchedInputException: Cannot construct instance of `com.netflix.spinnaker.orca.deploymentmonitor.models.DeploymentStep` (although at least one Creator exists): no String-argument constructor/factory method to deserialize from String value ('bogus')
 at [Source: (retrofit.ExceptionCatchingTypedInput$ExceptionCatchingInputStream); line: 1, column: 13] (through reference chain: com.netflix.spinnaker.orca.deploymentmonitor.models.EvaluateHealthResponse["nextStep"])
	at retrofit.RetrofitError.conversionError(RetrofitError.java:33)

after:

2024-01-04 16:14:03.540  WARN   --- [    Test worker] n.s.o.c.t.m.EvaluateDeploymentHealthTask : [] HTTP Error encountered while talking to monitorName(monitorId)->http://localhost:59402/deployment/evaluateHealth, <NO RESPONSE>}
com.netflix.spinnaker.kork.retrofit.exceptions.SpinnakerConversionException: com.fasterxml.jackson.databind.exc.MismatchedInputException: Cannot construct instance of `com.netflix.spinnaker.orca.deploymentmonitor.models.DeploymentStep` (although at least one Creator exists): no String-argument constructor/factory method to deserialize from String value ('bogus')
 at [Source: (retrofit.ExceptionCatchingTypedInput$ExceptionCatchingInputStream); line: 1, column: 13] (through reference chain: com.netflix.spinnaker.orca.deploymentmonitor.models.EvaluateHealthResponse["nextStep"])
	at com.netflix.spinnaker.kork.retrofit.exceptions.SpinnakerRetrofitErrorHandler.handleError(SpinnakerRetrofitErrorHandler.java:64)
	at retrofit.RestAdapter$RestHandler.invoke(RestAdapter.java:242)

---------

Co-authored-by: Pranav-b-7 <[email protected]>

orca-clouddriver/orca-clouddriver.gradle

@@ -55,6 +55,7 @@ dependencies {
   testImplementation("org.assertj:assertj-core")
   testImplementation("org.mockito:mockito-junit-jupiter")
   testImplementation("io.spinnaker.fiat:fiat-core:$fiatVersion")
+  testImplementation "io.spinnaker.kork:kork-test"
   testImplementation("dev.minutest:minutest")
   testImplementation("io.strikt:strikt-core")
   testImplementation("io.mockk:mockk")

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

@@ -16,10 +16,11 @@
 
 package com.netflix.spinnaker.orca.clouddriver.tasks.monitoreddeploy;
 
-import com.google.common.io.CharStreams;
+import com.fasterxml.jackson.databind.ObjectMapper;
 import com.netflix.spectator.api.Registry;
 import com.netflix.spinnaker.config.DeploymentMonitorDefinition;
-import com.netflix.spinnaker.kork.annotations.VisibleForTesting;
+import com.netflix.spinnaker.kork.retrofit.exceptions.SpinnakerHttpException;
+import com.netflix.spinnaker.kork.retrofit.exceptions.SpinnakerServerException;
 import com.netflix.spinnaker.orca.api.pipeline.RetryableTask;
 import com.netflix.spinnaker.orca.api.pipeline.TaskResult;
 import com.netflix.spinnaker.orca.api.pipeline.models.ExecutionStatus;
@@ -31,8 +32,6 @@
 import com.netflix.spinnaker.orca.deploymentmonitor.models.EvaluateHealthResponse;
 import com.netflix.spinnaker.orca.deploymentmonitor.models.MonitoredDeployInternalStageData;
 import com.netflix.spinnaker.orca.deploymentmonitor.models.StatusExplanation;
-import java.io.InputStreamReader;
-import java.nio.charset.StandardCharsets;
 import java.time.Duration;
 import java.util.*;
 import java.util.concurrent.TimeUnit;
@@ -41,9 +40,6 @@
 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 {
   static final int MAX_RETRY_COUNT = 3;
@@ -52,6 +48,7 @@ public class MonitoredDeployBaseTask implements RetryableTask {
   private DeploymentMonitorServiceProvider deploymentMonitorServiceProvider;
   private final Map<EvaluateHealthResponse.NextStepDirective, String> summaryMapping =
       new HashMap<>();
+  ObjectMapper objectMapper = new ObjectMapper();
 
   MonitoredDeployBaseTask(
       DeploymentMonitorServiceProvider deploymentMonitorServiceProvider, Registry registry) {
@@ -138,12 +135,12 @@ public long getDynamicTimeout(StageExecution stage) {
 
     try {
       return executeInternal(stage, monitorDefinition);
-    } catch (RetrofitError e) {
+    } catch (SpinnakerServerException e) {
       log.warn(
           "HTTP Error encountered while talking to {}->{}, {}}",
           monitorDefinition,
           e.getUrl(),
-          getRetrofitLogMessage(e.getResponse()),
+          getErrorMessage(e),
           e);
 
       return handleError(stage, e, true, monitorDefinition);
@@ -268,26 +265,51 @@ private MonitoredDeployStageData getStageContext(StageExecution stage) {
     return stage.mapTo(MonitoredDeployStageData.class);
   }
 
-  @VisibleForTesting
-  String getRetrofitLogMessage(Response response) {
-    if (response == null) {
+  private String getErrorMessage(SpinnakerServerException spinnakerException) {
+    if (!(spinnakerException instanceof SpinnakerHttpException)) {
       return "<NO RESPONSE>";
     }
 
+    SpinnakerHttpException httpException = (SpinnakerHttpException) spinnakerException;
+
     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));
+      status = String.format("%d (%s)", httpException.getResponseCode(), httpException.getReason());
+
+      // It's simplest to use the built-in string representation of
+      // httpException.getHeaders().  That's a change in behavior from the
+      // previous code though.  That code logged each header on its own line, e.g.:
+      //
+      // arbitrary-header-1: arbitrary-header-value-1
+      // arbitrary-header-2: arbitrary-header-value-2a
+      // arbitrary-header-2: arbitrary-header-value-2b
+      //
+      // where httpException.getHeaders().toString() is:
+      //
+      // headers: [arbitrary-header-1:"arbitrary-header-value-1",
+      // arbitrary-header-2:"arbitrary-header-value-2a", "arbitrary-header-value-2b"]
+      //
+      // To maintain that behavior, build our own string representation of the headers.
       headers =
-          response.getHeaders().stream().map(Header::toString).collect(Collectors.joining("\n"));
+          httpException.getHeaders().entrySet().stream()
+              .map(
+                  entry -> {
+                    List<String> values = entry.getValue();
+                    return values.stream()
+                        .map(value -> entry.getKey() + ": " + value)
+                        .collect(Collectors.toList());
+                  })
+              .flatMap(List::stream)
+              .collect(Collectors.joining("\n"));
+
+      if (httpException.getResponseBody() != null) {
+        body = objectMapper.writeValueAsString(httpException.getResponseBody());
+      }
     } catch (Exception e) {
-      log.error(
-          "Failed to fully parse retrofit error while reading response from deployment monitor", e);
+      log.error("Failed to fully process SpinnakerHttpException from deployment monitor", e);
     }
 
     return String.format("status: %s\nheaders: %s\nresponse body: %s", status, headers, body);

orca-clouddriver/src/test/groovy/com/netflix/spinnaker/orca/clouddriver/tasks/monitoreddeploy/EvaluateDeploymentHealthTaskSpec.groovy

@@ -18,6 +18,8 @@ package com.netflix.spinnaker.orca.clouddriver.tasks.monitoreddeploy
 
 import com.netflix.spectator.api.NoopRegistry
 import com.netflix.spinnaker.config.DeploymentMonitorDefinition
+import com.netflix.spinnaker.kork.retrofit.exceptions.SpinnakerHttpException
+import com.netflix.spinnaker.kork.retrofit.exceptions.SpinnakerServerException
 import com.netflix.spinnaker.orca.api.pipeline.models.ExecutionStatus
 import com.netflix.spinnaker.orca.api.pipeline.TaskResult
 import com.netflix.spinnaker.orca.deploymentmonitor.DeploymentMonitorService
@@ -41,11 +43,11 @@ class EvaluateDeploymentHealthTaskSpec extends Specification {
   PipelineExecutionImpl pipe = pipeline {
   }
 
-  def "should retry retrofit errors"() {
+  def "should retry on SpinnakerServerException"() {
     given:
     def monitorServiceStub = Stub(DeploymentMonitorService) {
       evaluateHealth(_) >> {
-        throw RetrofitError.networkError("url", new IOException())
+        throw new SpinnakerServerException(RetrofitError.networkError("url", new IOException()))
       }
     }
 

orca-clouddriver/src/test/groovy/com/netflix/spinnaker/orca/clouddriver/tasks/servergroup/ServerGroupCacheForceRefreshTaskSpec.groovy

@@ -85,7 +85,7 @@ class ServerGroupCacheForceRefreshTaskSpec extends Specification {
   void "should auto-succeed if force cache refresh takes longer than 12 minutes"() {
     setup:
     task.clock = Mock(Clock) {
-      1 * millis() >> TimeUnit.MINUTES.toMillis(12) + 1
+      2 * millis() >> TimeUnit.MINUTES.toMillis(12) + 1
     }
 
     expect: