OKAPI-1193: Clearly log which user/tenant has invalid credentials

okapi-common/src/main/java/org/folio/okapi/common/refreshtoken/client/impl/LoginClient.java

@@ -8,6 +8,8 @@
 import io.vertx.core.json.JsonObject;
 import io.vertx.ext.web.client.HttpRequest;
 import java.util.function.Supplier;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
 import org.folio.okapi.common.Constants;
 import org.folio.okapi.common.XOkapiHeaders;
 import org.folio.okapi.common.refreshtoken.client.Client;
@@ -18,6 +20,8 @@
 @java.lang.SuppressWarnings({"squid:S1075"}) // URIs should not be hardcoded
 public class LoginClient implements Client {
 
+  private static final Logger LOGGER = LogManager.getLogger(LoginClient.class);
+
   private static final String LOGIN_EXPIRY_PATH = "/authn/login-with-expiry";
 
   private static final String LOGIN_LEGACY_PATH = "/authn/login";
@@ -63,12 +67,16 @@ Future<String> getTokenLegacy(JsonObject payload) {
           .putHeader(XOkapiHeaders.TENANT, tenant)
           .sendJsonObject(payload).map(res -> {
             if (res.statusCode() != 201) {
-              throw new ClientException("POST " + LOGIN_LEGACY_PATH + " returned status "
-                  + res.statusCode() + ": " + res.bodyAsString());
+              var msg = loginFailed(LOGIN_LEGACY_PATH)
+                  + " returned status " + res.statusCode() + ": " + res.bodyAsString();
+              LOGGER.error("{}", msg);
+              throw new ClientException(msg);
             }
             String token = res.getHeader(XOkapiHeaders.TOKEN);
             if (token == null) {
-              throw new ClientException(LOGIN_LEGACY_PATH + " did not return token");
+              var msg = loginFailed(LOGIN_LEGACY_PATH) + " did not return token.";
+              LOGGER.error("{}", msg);
+              throw new ClientException(msg);
             }
             if (cache != null) {
               cache.put(tenant, username, token,
@@ -91,8 +99,10 @@ Future<String> getTokenWithExpiry(JsonObject payload) {
             if (res.statusCode() == 404) {
               return null;
             } else if (res.statusCode() != 201) {
-              throw new ClientException("POST " + LOGIN_EXPIRY_PATH + " returned status "
-                  + res.statusCode() + ": " + res.bodyAsString());
+              var msg = loginFailed(LOGIN_EXPIRY_PATH)
+                  + " returned status " + res.statusCode() + ": " + res.bodyAsString();
+              LOGGER.error("{}", msg);
+              throw new ClientException(msg);
             }
             for (String v : res.cookies()) {
               Cookie cookie = ClientCookieDecoder.STRICT.decode(v);
@@ -105,13 +115,20 @@ Future<String> getTokenWithExpiry(JsonObject payload) {
                 return cookie.value();
               }
             }
-            throw new ClientException(LOGIN_EXPIRY_PATH + " did not return access token");
+            var msg = loginFailed(LOGIN_EXPIRY_PATH) + " did not return access token";
+            LOGGER.error("{}", msg);
+            throw new ClientException(msg);
           });
     } catch (Exception e) {
       return Future.failedFuture(e);
     }
   }
 
+  private String loginFailed(String path) {
+    return "Login failed. POST " + path
+        + " for tenant '" + tenant + "' and username '" + username + "'";
+  }
+
   @Override
   public Future<String> getToken() {
     if (cache != null) {

okapi-common/src/main/java/org/folio/okapi/common/refreshtoken/client/impl/RefreshClient.java

@@ -7,16 +7,22 @@
 import io.vertx.core.http.HttpHeaders;
 import io.vertx.ext.web.client.HttpRequest;
 import io.vertx.ext.web.client.HttpResponse;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
 import org.folio.okapi.common.Constants;
+import org.folio.okapi.common.OkapiToken;
 import org.folio.okapi.common.XOkapiHeaders;
 import org.folio.okapi.common.refreshtoken.client.Client;
 import org.folio.okapi.common.refreshtoken.client.ClientException;
 import org.folio.okapi.common.refreshtoken.client.ClientOptions;
 import org.folio.okapi.common.refreshtoken.tokencache.RefreshTokenCache;
 
-@java.lang.SuppressWarnings({"squid:S1075"}) // URIs should not be hardcoded
+@SuppressWarnings({"squid:S1075"}) // URIs should not be hardcoded
 public class RefreshClient implements Client {
 
+  private static final Logger LOGGER = LogManager.getLogger(RefreshClient.class);
+
+  private static final int PAYLOAD_LOGGING_MAX_LENGTH = 200;
   private static final String REFRESH_PATH = "/authn/refresh";
 
   private final ClientOptions clientOptions;
@@ -75,8 +81,11 @@ public Future<HttpRequest<Buffer>> getToken(HttpRequest<Buffer> request) {
 
   String tokenResponse(HttpResponse<Buffer> res) {
     if (res.statusCode() != 201) {
-      throw new ClientException("POST " + REFRESH_PATH + " returned status "
-          + res.statusCode() + ": " + res.bodyAsString());
+      var msg = "Token refresh failed. POST " + REFRESH_PATH
+          + " for tenant '" + tenant + "' and refreshtoken '" + payload()
+          + "' returned status " + res.statusCode() + ": " + res.bodyAsString();
+      LOGGER.error("{}", msg);
+      throw new ClientException(msg);
     }
     for (String v: res.cookies()) {
       io.netty.handler.codec.http.cookie.Cookie cookie = ClientCookieDecoder.STRICT.decode(v);
@@ -89,7 +98,25 @@ String tokenResponse(HttpResponse<Buffer> res) {
         return cookie.value();
       }
     }
-    throw new ClientException(REFRESH_PATH + " did not return access token");
+    var msg = "Token refresh failed. POST " + REFRESH_PATH
+        + " for tenant '" + tenant + "' and refreshtoken '" + payload()
+        + "' did not return access token";
+    LOGGER.error("{}", msg);
+    throw new ClientException(msg);
   }
 
+  @SuppressWarnings({ // don't throw exceptions while logging an error
+      "java:S1166", // suppress "Either log or rethrow this exception."
+      "java:S2221", // suppress "Catch a list of specific exception subtypes instead."
+  })
+  String payload() {
+    if (refreshToken != null && refreshToken.length() > PAYLOAD_LOGGING_MAX_LENGTH) {
+      return "too long: " + refreshToken.substring(0, PAYLOAD_LOGGING_MAX_LENGTH) + "...";
+    }
+    try {
+      return new OkapiToken(refreshToken).getPayloadWithoutValidation().encode();
+    } catch (Exception e) {
+      return "invalid: " + refreshToken;
+    }
+  }
 }

okapi-common/src/test/java/org/folio/okapi/common/refreshtoken/client/impl/LoginClientTest.java

@@ -212,7 +212,8 @@ public void nullPassword(TestContext context) {
             .putHeader("Content-Type", "text/xml")
             .expect(SC_BAD_REQUEST))
         .onComplete(context.asyncAssertFailure(t -> {
-          assertThat(t.getMessage(), is("POST /authn/login returned status 400: "
+          assertThat(t.getMessage(), is("Login failed. POST /authn/login "
+              + "for tenant 'diku' and username 'dikuuser' returned status 400: "
               + "Bad tenant/username/password"));
           assertThat(countLoginWithExpiry, is(0));
         }));
@@ -252,7 +253,8 @@ public void legacyNoToken(TestContext context) {
             .putHeader("Content-Type", "text/xml")
             .expect(SC_CREATED))
         .onComplete(context.asyncAssertFailure(cause ->
-            assertThat(cause.getMessage(), is("/authn/login did not return token"))
+            assertThat(cause.getMessage(), is("Login failed. POST /authn/login "
+                + "for tenant 'diku' and username 'dikuuser' did not return token."))
         ));
   }
 
@@ -301,7 +303,8 @@ public void withExpiryNoCookies(TestContext context) {
             .putHeader("Content-Type", "text/xml")
             .expect(SC_CREATED))
         .onComplete(context.asyncAssertFailure(response -> {
-          assertThat(response.getMessage(), is("/authn/login-with-expiry did not return access token"));
+          assertThat(response.getMessage(), is("Login failed. POST /authn/login-with-expiry "
+              + "for tenant 'diku' and username 'dikuuser' did not return access token"));
         }));
   }
 
@@ -338,8 +341,8 @@ public void badPasswordWithExpiry(TestContext context) {
         .onComplete(context.asyncAssertFailure(e -> {
           assertThat(countLoginWithExpiry, is(1));
           assertThat(e, Matchers.instanceOf(ClientException.class));
-          assertThat(e.getMessage(), is("POST /authn/login-with-expiry returned status 400: "
-              + "Bad tenant/username/password"));
+          assertThat(e.getMessage(), is("Login failed. POST /authn/login-with-expiry "
+              + "for tenant 'diku' and username 'dikuuser' returned status 400: Bad tenant/username/password"));
         }));
   }
 

okapi-common/src/test/java/org/folio/okapi/common/refreshtoken/client/impl/RefreshClientTest.java

@@ -2,15 +2,21 @@
 
 import static org.folio.okapi.common.ChattyResponsePredicate.SC_BAD_REQUEST;
 import static org.folio.okapi.common.ChattyResponsePredicate.SC_CREATED;
+import static org.hamcrest.CoreMatchers.endsWith;
 import static org.hamcrest.CoreMatchers.is;
+import static org.hamcrest.CoreMatchers.startsWith;
 import static org.hamcrest.MatcherAssert.assertThat;
 
+import java.nio.charset.StandardCharsets;
+import java.util.Base64;
+
 import io.vertx.core.Vertx;
 import io.vertx.core.buffer.Buffer;
 import io.vertx.core.http.Cookie;
 import io.vertx.core.http.CookieSameSite;
 import io.vertx.core.http.HttpServerRequest;
 import io.vertx.core.http.HttpServerResponse;
+import io.vertx.core.json.JsonObject;
 import io.vertx.ext.unit.TestContext;
 import io.vertx.ext.unit.junit.VertxUnitRunner;
 import io.vertx.ext.web.Router;
@@ -192,8 +198,8 @@ public void refreshInvalidToken(TestContext context) {
             .putHeader("Content-Type", "text/xml")
             .expect(SC_BAD_REQUEST))
         .onComplete(context.asyncAssertFailure(response ->
-          assertThat(response.getMessage(), is("POST /authn/refresh returned status 400: "
-              + "Missing/bad refresh token"))
+          assertThat(response.getMessage(), is("Token refresh failed. POST /authn/refresh "
+              + "for tenant 'diku' and refreshtoken 'invalid: invalid_token' returned status 400: Missing/bad refresh token"))
         ));
   }
 
@@ -238,7 +244,8 @@ public void refreshNotFound(TestContext context) {
     client.getToken(webClient.postAbs(OKAPI_URL + "/echo")
             .expect(SC_CREATED))
         .onComplete(context.asyncAssertFailure(cause ->
-          assertThat(cause.getMessage(), is("POST /authn/refresh returned status 404: Not found"))
+          assertThat(cause.getMessage(), is("Token refresh failed. POST /authn/refresh "
+              + "for tenant 'diku' and refreshtoken 'invalid: diku' returned status 404: Not found"))
         ));
   }
 
@@ -249,7 +256,8 @@ public void refreshNoCookiesReturned(TestContext context) {
     client.getToken(webClient.postAbs(OKAPI_URL + "/echo")
             .expect(SC_CREATED))
         .onComplete(context.asyncAssertFailure(cause ->
-            assertThat(cause.getMessage(), is("/authn/refresh did not return access token"))
+            assertThat(cause.getMessage(), is("Token refresh failed. POST /authn/refresh "
+                + "for tenant 'diku' and refreshtoken 'invalid: diku' did not return access token"))
         ));
   }
 
@@ -263,4 +271,30 @@ public void getTokenMalformedUrl(TestContext context) {
             assertThat(e.getMessage(), is("java.net.MalformedURLException: no protocol: x/authn/refresh")
         )));
   }
+
+  @Test
+  public void payload() {
+    var payload = new RefreshClient(null, null, "diku", "foo." + urlEncode("{}") + ".baz").payload();
+    assertThat(payload, is("{}"));
+  }
+
+  @Test
+  public void payloadTooLong() {
+    var json = new JsonObject().put("x", "s".repeat(200)).encode();
+    var payload = new RefreshClient(null, null, "diku", "foo." + urlEncode(json) + ".baz").payload();
+    assertThat(payload, startsWith("too long: foo.eyJ4Ijoic3Nz"));
+    assertThat(payload, endsWith("..."));
+  }
+
+  @Test
+  public void payloadInvalid() {
+    var payload = new RefreshClient(null, null, "diku", "foo.bar.baz").payload();
+    assertThat(payload, is("invalid: foo.bar.baz"));
+  }
+
+  private String urlEncode(String s) {
+    return new String(
+        Base64.getUrlEncoder().encode(s.getBytes(StandardCharsets.UTF_8)),
+        StandardCharsets.UTF_8);
+  }
 }