diff --git a/okapi-common/src/main/java/org/folio/okapi/common/refreshtoken/client/impl/LoginClient.java b/okapi-common/src/main/java/org/folio/okapi/common/refreshtoken/client/impl/LoginClient.java index 7895dc4b0..763cc5074 100644 --- a/okapi-common/src/main/java/org/folio/okapi/common/refreshtoken/client/impl/LoginClient.java +++ b/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 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 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 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 getToken() { if (cache != null) { diff --git a/okapi-common/src/main/java/org/folio/okapi/common/refreshtoken/client/impl/RefreshClient.java b/okapi-common/src/main/java/org/folio/okapi/common/refreshtoken/client/impl/RefreshClient.java index 99eef2f50..1ee51f495 100644 --- a/okapi-common/src/main/java/org/folio/okapi/common/refreshtoken/client/impl/RefreshClient.java +++ b/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> getToken(HttpRequest request) { String tokenResponse(HttpResponse 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 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; + } + } } diff --git a/okapi-common/src/test/java/org/folio/okapi/common/refreshtoken/client/impl/LoginClientTest.java b/okapi-common/src/test/java/org/folio/okapi/common/refreshtoken/client/impl/LoginClientTest.java index c4dfb6bdf..5cc660d52 100644 --- a/okapi-common/src/test/java/org/folio/okapi/common/refreshtoken/client/impl/LoginClientTest.java +++ b/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")); })); } diff --git a/okapi-common/src/test/java/org/folio/okapi/common/refreshtoken/client/impl/RefreshClientTest.java b/okapi-common/src/test/java/org/folio/okapi/common/refreshtoken/client/impl/RefreshClientTest.java index 85a6d350d..6b80ce0fa 100644 --- a/okapi-common/src/test/java/org/folio/okapi/common/refreshtoken/client/impl/RefreshClientTest.java +++ b/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); + } }