Merge pull request #506 from spotify/request-ids

assign UUIDs to all requests and their logs

styx-cli/src/main/java/com/spotify/styx/cli/CliMain.java

@@ -298,19 +298,20 @@ private void run() {
         if (apiError.getCode() == UNAUTHORIZED.code()) {
           if (!apiError.isAuthenticated()) {
             cliOutput.printError(
-                "API error: Unauthorized: Please set up Application Default Credentials or set the "
+                "API error: Unauthorized: " + apiError.getMessage() + "\n"
+                    + "Please set up Application Default Credentials or set the "
                     + "GOOGLE_APPLICATION_CREDENTIALS env var to point to a file defining the "
                     + "credentials.\n"
                     + "\n"
                     + "Hint: Try setting up credentials using gcloud: \n"
                     + "\n"
                     + "\t$ gcloud auth application-default login");
           } else {
-            cliOutput.printError("API error: Unauthorized");
+            cliOutput.printError("API error: Unauthorized: " + apiError.getMessage());
           }
           throw CliExitException.of(ExitStatus.AuthError);
         } else {
-          cliOutput.printError("API error: " + cause.getMessage());
+          cliOutput.printError("API error: " + apiError.getMessage());
           throw CliExitException.of(ExitStatus.ApiError);
         }
       } else if (cause instanceof ClientErrorException) {

styx-cli/src/test/java/com/spotify/styx/cli/CliMainTest.java

@@ -64,6 +64,7 @@
 import java.util.Collections;
 import java.util.List;
 import java.util.Optional;
+import java.util.UUID;
 import java.util.concurrent.CompletableFuture;
 import junitparams.JUnitParamsRunner;
 import junitparams.Parameters;
@@ -86,6 +87,8 @@ public class CliMainTest {
   @Mock CliOutput cliOutput;
   @Mock WorkflowValidator validator;
 
+  private String requestId = UUID.randomUUID().toString();
+
   @Before
   public void setUp() {
     MockitoAnnotations.initMocks(this);
@@ -488,7 +491,7 @@ public void shouldHandleWorkflowNotFoundWhenEnabling() {
         .enabled(true)
         .build();
 
-    final ApiErrorException exception = new ApiErrorException("not found", 404, true);
+    final ApiErrorException exception = new ApiErrorException("not found", 404, true, requestId);
     when(client.updateWorkflowState(any(), any(), eq(workflowState)))
         .thenReturn(exceptionallyCompletedFuture(exception));
 
@@ -504,7 +507,7 @@ public void shouldHandleWorkflowNotFoundWhenDisabling() {
         .enabled(false)
         .build();
 
-    final ApiErrorException exception = new ApiErrorException("not found", 404, true);
+    final ApiErrorException exception = new ApiErrorException("not found", 404, true, requestId);
     when(client.updateWorkflowState(any(), any(), eq(workflowState)))
         .thenReturn(exceptionallyCompletedFuture(exception));
 
@@ -552,7 +555,7 @@ public void testClientErrorDebug() {
 
   @Test
   public void testApiError() {
-    final ApiErrorException exception = new ApiErrorException("bar failure", 500, true);
+    final ApiErrorException exception = new ApiErrorException("bar failure", 500, true, requestId);
     when(client.triggerWorkflowInstance(any(), any(), any()))
         .thenReturn(exceptionallyCompletedFuture(exception));
 
@@ -601,8 +604,9 @@ public void testUnknownError() {
 
   @Test
   public void testMissingCredentialsHelpMessage() {
+    final ApiErrorException apiError = new ApiErrorException("foo", 401, false, requestId);
     when(client.triggerWorkflowInstance(any(), any(), any()))
-        .thenReturn(exceptionallyCompletedFuture(new ApiErrorException("foo", 401, false)));
+        .thenReturn(exceptionallyCompletedFuture(apiError));
 
     try {
       CliMain.run(cliContext, "t", "foo", "bar", "2017-01-02");
@@ -612,12 +616,14 @@ public void testMissingCredentialsHelpMessage() {
     }
 
     verify(cliOutput).printError(contains("gcloud auth application-default login"));
+    verify(cliOutput).printError(contains(apiError.getMessage()));
   }
 
   @Test
   public void testUnauthorizedMessage() {
+    final ApiErrorException apiError = new ApiErrorException("foo", 401, true, requestId);
     when(client.triggerWorkflowInstance(any(), any(), any()))
-        .thenReturn(exceptionallyCompletedFuture(new ApiErrorException("foo", 401, true)));
+        .thenReturn(exceptionallyCompletedFuture(apiError));
 
     try {
       CliMain.run(cliContext, "t", "foo", "bar", "2017-01-02");
@@ -626,7 +632,7 @@ public void testUnauthorizedMessage() {
       assertThat(e.status(), is(ExitStatus.AuthError));
     }
 
-    verify(cliOutput).printError("API error: Unauthorized");
+    verify(cliOutput).printError("API error: Unauthorized: " + apiError.getMessage());
   }
 
   @Test

styx-client/pom.xml

@@ -36,6 +36,12 @@
       <artifactId>google-api-services-iam</artifactId>
     </dependency>
 
+    <dependency>
+      <groupId>com.spotify</groupId>
+      <artifactId>styx-test</artifactId>
+      <version>${project.version}</version>
+      <scope>test</scope>
+    </dependency>
     <dependency>
       <groupId>junit</groupId>
       <artifactId>junit</artifactId>

styx-client/src/main/java/com/spotify/styx/client/ApiErrorException.java

@@ -28,11 +28,13 @@ public class ApiErrorException extends RuntimeException {
 
   private final int code;
   private final boolean authenticated;
+  private final String requestId;
 
-  public ApiErrorException(String message, int code, boolean authenticated) {
+  public ApiErrorException(String message, int code, boolean authenticated, String requestId) {
     super(message);
     this.code = code;
     this.authenticated = authenticated;
+    this.requestId = requestId;
   }
 
   public int getCode() {
@@ -42,4 +44,16 @@ public int getCode() {
   public boolean isAuthenticated() {
     return authenticated;
   }
+
+  public String getRequestId() {
+    return requestId;
+  }
+
+  @Override
+  public String getMessage() {
+    final String message = super.getMessage();
+    return requestId == null || message.contains(requestId)
+        ? message
+        : message + " (Request ID: " + requestId + ")";
+  }
 }

styx-client/src/main/java/com/spotify/styx/client/ClientErrorException.java

@@ -25,4 +25,8 @@ public class ClientErrorException extends RuntimeException {
   public ClientErrorException(String message, Throwable cause) {
     super(message, cause);
   }
+
+  public ClientErrorException(String message) {
+    super(message);
+  }
 }

styx-client/src/main/java/com/spotify/styx/client/StyxApolloClient.java

@@ -58,6 +58,7 @@
 import java.util.List;
 import java.util.Objects;
 import java.util.Optional;
+import java.util.UUID;
 import java.util.concurrent.CompletionStage;
 import okhttp3.HttpUrl;
 import okhttp3.HttpUrl.Builder;
@@ -69,10 +70,12 @@
  * as {@link RuntimeException} instead.
  */
 class StyxApolloClient implements StyxClient {
+
   private static final String STYX_API_VERSION = V3.name().toLowerCase();
   private static final String STYX_CLIENT_VERSION =
       "Styx Client " + StyxApolloClient.class.getPackage().getImplementationVersion();
   private static final Duration TTL = Duration.ofSeconds(90);
+  private static final String X_REQUEST_ID = "X-Request-Id";
 
   private final URI apiHost;
   private final Client client;
@@ -418,9 +421,10 @@ private <T> CompletionStage<T> executeRequest(final Request request,
   }
 
   private Request decorateRequest(
-      final Request request, final Optional<String> authToken) {
+      final Request request, String requestId, final Optional<String> authToken) {
     return request
         .withHeader("User-Agent", STYX_CLIENT_VERSION)
+        .withHeader("X-Request-Id", requestId)
         .withTtl(TTL)
         .withHeaders(authToken
             .map(t -> ImmutableMap.of("Authorization", "Bearer " + t))
@@ -436,16 +440,21 @@ private CompletionStage<Response<ByteString>> executeRequest(final Request reque
       return CompletableFutures.exceptionallyCompletedFuture(
           new ClientErrorException("Authentication failure: " + e.getMessage(), e));
     }
-    return client.send(decorateRequest(request, authToken)).handle((response, e) -> {
+    final String requestId = UUID.randomUUID().toString().replace("-", "");  // UUID with no dashes, easier to deal with
+    return client.send(decorateRequest(request, requestId, authToken)).handle((response, e) -> {
       if (e != null) {
         throw new ClientErrorException("Request failed: " + request.method() + " " + request.uri(), e);
       } else {
+        final String responseRequestId = response.headers().get(X_REQUEST_ID);
+        if (responseRequestId != null && !responseRequestId.equals(requestId)) {
+          throw new ClientErrorException("Request ID mismatch: '" + requestId + "' != '" + responseRequestId + "'");
+        }
         switch (response.status().family()) {
           case SUCCESSFUL:
             return response;
           default:
             final String message = response.status().code() + " " + response.status().reasonPhrase();
-            throw new ApiErrorException(message, response.status().code(), authToken.isPresent());
+            throw new ApiErrorException(message, response.status().code(), authToken.isPresent(), responseRequestId);
         }
       }
     });

styx-client/src/test/java/com/spotify/styx/client/ApiErrorExceptionTest.java

@@ -0,0 +1,51 @@
+/*
+ * -\-\-
+ * Spotify Styx Scheduler Service
+ * --
+ * Copyright (C) 2018 Spotify AB
+ * --
+ * 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.spotify.styx.client;
+
+import static org.hamcrest.Matchers.is;
+import static org.junit.Assert.assertThat;
+
+import java.util.UUID;
+import org.junit.Test;
+
+public class ApiErrorExceptionTest {
+
+  private static final String REQUEST_ID = UUID.randomUUID().toString();
+
+  @Test
+  public void getMessage() {
+    final String message = "fubared: rid=" + REQUEST_ID;
+    ApiErrorException exception = new ApiErrorException(message, 4711, true, REQUEST_ID);
+    assertThat(exception.getMessage(), is(message));
+  }
+
+  @Test
+  public void getMessageNoRequestIdInMessage() {
+    ApiErrorException exception = new ApiErrorException("fubared!", 4711, true, REQUEST_ID);
+    assertThat(exception.getMessage(), is("fubared! (Request ID: " + REQUEST_ID + ")"));
+  }
+
+  @Test
+  public void getMessageNoRequestId() {
+    ApiErrorException exception = new ApiErrorException("fubared!", 4711, true, null);
+    assertThat(exception.getMessage(), is("fubared!"));
+  }
+}

styx-client/src/test/java/com/spotify/styx/client/StyxApolloClientTest.java

@@ -33,6 +33,8 @@
 import static org.mockito.Mockito.verify;
 import static org.mockito.Mockito.when;
 
+import static com.spotify.styx.util.StringIsValidUuid.isValidUuid;
+import com.fasterxml.jackson.core.JsonProcessingException;
 import com.google.common.collect.ImmutableList;
 import com.spotify.apollo.Client;
 import com.spotify.apollo.Request;
@@ -50,6 +52,7 @@
 import com.spotify.styx.serialization.Json;
 import java.io.IOException;
 import java.time.Instant;
+import java.util.Collections;
 import java.util.List;
 import java.util.Optional;
 import java.util.concurrent.CompletableFuture;
@@ -322,4 +325,34 @@ public void testUnauthorizedWithCredentialsApiError() throws Exception {
       assertThat(apiErrorException.isAuthenticated(), is(true));
     }
   }
+
+  @Test
+  public void testSendsRequestId() throws JsonProcessingException {
+    final StyxApolloClient styx = new StyxApolloClient(client, CLIENT_HOST, auth);
+    when(client.send(requestCaptor.capture())).thenReturn(CompletableFuture.completedFuture(
+        Response.forStatus(Status.OK).withPayload(Json.serialize(Collections.emptyList()))));
+    styx.workflows();
+    final Request request = requestCaptor.getValue();
+    assertThat(request.header("X-Request-Id").get(), isValidUuid());
+  }
+
+  @Test
+  public void testErrorOnRequestIdMismatch() throws JsonProcessingException, InterruptedException {
+    final StyxApolloClient styx = new StyxApolloClient(client, CLIENT_HOST, auth);
+    when(client.send(requestCaptor.capture())).thenReturn(CompletableFuture.completedFuture(
+        Response.forStatus(Status.OK)
+            .withHeader("X-Request-Id", "foobar")
+            .withPayload(Json.serialize(Collections.emptyList()))));
+
+    try {
+      styx.workflows().toCompletableFuture().get();
+      fail();
+    } catch (ExecutionException e) {
+      final Request request = requestCaptor.getValue();
+      final String requestId = request.header("X-Request-Id").get();
+      final Throwable cause = e.getCause();
+      assertThat(cause, instanceOf(ClientErrorException.class));
+      assertThat(cause.getMessage(), is("Request ID mismatch: '" + requestId + "' != 'foobar'"));
+    }
+  }
 }

styx-common/pom.xml

@@ -137,5 +137,10 @@
       <artifactId>JUnitParams</artifactId>
       <scope>test</scope>
     </dependency>
+    <dependency>
+      <groupId>ch.qos.logback</groupId>
+      <artifactId>logback-classic</artifactId>
+      <scope>test</scope>
+    </dependency>
   </dependencies>
 </project>

styx-common/src/main/java/com/spotify/styx/api/Api.java

@@ -21,7 +21,7 @@
 package com.spotify.styx.api;
 
 import static com.spotify.styx.api.Middlewares.clientValidator;
-import static com.spotify.styx.api.Middlewares.exceptionHandler;
+import static com.spotify.styx.api.Middlewares.exceptionAndRequestIdHandler;
 import static com.spotify.styx.api.Middlewares.httpLogger;
 
 import com.spotify.apollo.Response;
@@ -62,7 +62,7 @@ public static Stream<Route<AsyncHandler<Response<ByteString>>>> withCommonMiddle
     return routes.map(r -> r
         .withMiddleware(httpLogger())
         .withMiddleware(clientValidator(clientBlacklistSupplier))
-        .withMiddleware(exceptionHandler()));
+        .withMiddleware(exceptionAndRequestIdHandler()));
   }
   private Api() {
   }