diff --git a/README.md b/README.md index 92ee0ea..c9979eb 100644 --- a/README.md +++ b/README.md @@ -163,6 +163,31 @@ If you're creating and managing your signing key pair yourself, see the required Please refer to the [contributing guide](CONTRIBUTING.md). +# Logging + +All logger names start with "com.factset". + +This library uses [SLF4J](https://www.slf4j.org/) as logging interface, +which requires a [binding](https://www.slf4j.org/manual.html#swapping) to your logging framework on the classpath. + +If no binding is found, SLF4J prints out the following warning and then defaults to a no-operation +implementation, which discard all logs: +``` +SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder". +SLF4J: Defaulting to no-operation (NOP) logger implementation +SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details. +``` + +# Troubleshooting + +### "Unsuccessful token response: Failed to authenticate or parse the token" + +This error occurs when the request for an OAuth 2.0 Access Token got a non-200 response +that could not be parsed as an [OAuth 2.0 Error Response](https://www.rfc-editor.org/rfc/rfc6749.html#section-5.2). + +Additional logging can be enabled to troubleshoot the problem: +The logger `com.factset.sdk.utils.authentication.ConfidentialClient` logs out the exact response in log level `TRACE`. + # Copyright Copyright 2022 FactSet Research Systems Inc diff --git a/build.gradle b/build.gradle index aaab74d..0966a99 100644 --- a/build.gradle +++ b/build.gradle @@ -13,14 +13,19 @@ version '1.0.0' dependencies { implementation 'org.slf4j:slf4j-api:1.7.36' - implementation 'org.slf4j:slf4j-simple:1.7.36' implementation 'com.nimbusds:nimbus-jose-jwt:9.23' implementation 'org.json:json:20220320' implementation 'org.apache.httpcomponents:httpclient:4.5.13' implementation 'com.nimbusds:oauth2-oidc-sdk:9.37.3' + testImplementation 'org.mockito:mockito-core:4.6.1' testImplementation 'org.junit.jupiter:junit-jupiter-api:5.8.2' + testImplementation 'ch.qos.logback:logback-classic:1.2.11' + testImplementation "com.github.tomakehurst:wiremock-jre8-standalone:2.33.2" + testImplementation "org.assertj:assertj-core:3.23.1" + testImplementation "org.hamcrest:hamcrest:2.2" testRuntimeOnly 'org.junit.jupiter:junit-jupiter-engine:5.8.2' + testRuntimeOnly 'ch.qos.logback:logback-core:1.2.11' } task sourcesJar(type: Jar) { diff --git a/src/main/java/com/factset/sdk/utils/authentication/ConfidentialClient.java b/src/main/java/com/factset/sdk/utils/authentication/ConfidentialClient.java index 04f9ac9..4ad490b 100644 --- a/src/main/java/com/factset/sdk/utils/authentication/ConfidentialClient.java +++ b/src/main/java/com/factset/sdk/utils/authentication/ConfidentialClient.java @@ -17,6 +17,7 @@ import com.nimbusds.oauth2.sdk.TokenRequest; import com.nimbusds.oauth2.sdk.TokenResponse; import com.nimbusds.oauth2.sdk.auth.JWTAuthenticationClaimsSet; +import com.nimbusds.oauth2.sdk.http.HTTPRequest; import com.nimbusds.oauth2.sdk.http.HTTPResponse; import com.nimbusds.oauth2.sdk.id.Audience; import com.nimbusds.oauth2.sdk.id.ClientID; @@ -170,7 +171,13 @@ private String fetchAccessToken() throws AccessTokenException, SigningJwsExcepti try { final SignedJWT signedJwt = this.getSignedJwt(); final TokenRequest tokenRequest = this.tokenRequestBuilder.signedJwt(signedJwt).build(); - final HTTPResponse res = tokenRequest.toHTTPRequest().send(); + + final HTTPRequest httpRequest = tokenRequest.toHTTPRequest(); + logTokenRequest(httpRequest); + + final HTTPResponse res = httpRequest.send(); + logTokenResponse(res); + tokenRes = TokenResponse.parse(res); } catch (final IOException | ParseException e) { throw new AccessTokenException("Error attempting to get the access token", e); @@ -193,9 +200,26 @@ private String fetchAccessToken() throws AccessTokenException, SigningJwsExcepti tokenRes.toErrorResponse().getErrorObject().getDescription()); } - protected SignedJWT getSignedJwt() throws SigningJwsException { + private void logTokenRequest(HTTPRequest req) + { + LOGGER.trace( + "Token Request: {} {} headers={} body={}", + req.getMethod(), req.getURL(), req.getHeaderMap(), req.getQuery() + ); + } + + private static void logTokenResponse(HTTPResponse res) + { + LOGGER.trace( + "Token Response: {} {} headers={} body={}", + res.getStatusCode(), res.getStatusMessage(), res.getHeaderMap(), res.getContent() + ); + } + + protected SignedJWT getSignedJwt() throws SigningJwsException + { LOGGER.debug("Signing the JWT..."); - + final RSAKey jwk = this.config.getJwk(); final RSASSASigner signer; try { diff --git a/src/test/java/com/factset/sdk/utils/authentication/ConfidentialClientIT.java b/src/test/java/com/factset/sdk/utils/authentication/ConfidentialClientIT.java new file mode 100644 index 0000000..e29725c --- /dev/null +++ b/src/test/java/com/factset/sdk/utils/authentication/ConfidentialClientIT.java @@ -0,0 +1,115 @@ +package com.factset.sdk.utils.authentication; + +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.LoggerContext; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; +import com.factset.sdk.utils.exceptions.AccessTokenException; +import com.github.tomakehurst.wiremock.junit5.WireMockRuntimeInfo; +import com.github.tomakehurst.wiremock.junit5.WireMockTest; +import com.nimbusds.jose.jwk.RSAKey; +import org.assertj.core.api.ListAssert; +import org.junit.jupiter.api.BeforeAll; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; +import org.slf4j.LoggerFactory; + +import java.nio.file.Paths; + +import static com.github.tomakehurst.wiremock.client.WireMock.*; +import static java.nio.file.Files.readAllBytes; +import static org.assertj.core.api.Assertions.assertThat; +import static org.assertj.core.api.HamcrestCondition.matching; +import static org.hamcrest.Matchers.startsWith; +import static org.junit.jupiter.api.Assertions.assertThrows; + +@WireMockTest +public class ConfidentialClientIT +{ + private static Configuration configuration = null; + + @BeforeAll + static void prepare_config(WireMockRuntimeInfo wm) throws Exception + { + configuration = new Configuration( + "testClientId", + "testAuthType", + RSAKey.parse(ConfidentialClientTest.validJwk), + String.format("http://localhost:%d/well-known", wm.getHttpPort())); + } + + @BeforeEach + void setup_well_known_url_stub(WireMockRuntimeInfo wm) throws Exception + { + String wellKnown = new String(readAllBytes(Paths.get("./src/test/resources/well-known-uri-response.json"))) + .replace("https://example.com", String.format("http://localhost:%d", wm.getHttpPort())); + + stubFor(get("/well-known").willReturn(okJson(wellKnown))); + } + + @Test + void logs_request_and_response_for_success() + { + stubFor(post("/as/token.oauth2").willReturn(okJson( + "{\"access_token\":\"xxx_access_token\",\"token_type\":\"Bearer\",\"expires_in\":1234}"))); + + assertThatLogs(() -> new ConfidentialClient(configuration).getAccessToken()) + .map(log -> log.getLevel() + ":" + log.getFormattedMessage()) + .haveAtLeastOne(matching(startsWith("TRACE:Token Request: POST"))) + .haveAtLeastOne(matching(startsWith("TRACE:Token Response: 200 OK"))); + } + + @Test + void logs_request_and_response_for_error() + { + stubFor(post("/as/token.oauth2").willReturn(badRequest())); + + assertThatLogs(AccessTokenException.class, () -> new ConfidentialClient(configuration).getAccessToken()) + .map(log -> log.getLevel() + ":" + log.getFormattedMessage()) + .haveAtLeastOne(matching(startsWith("TRACE:Token Request: POST"))) + .haveAtLeastOne(matching(startsWith("TRACE:Token Response: 400 Bad Request"))); + } + + private static ListAssert assertThatLogs(ThrowingRunnable test) + { + // get a handle to the underlying logger + // and add our own appender to it to intercept logs + LoggerContext lc = (LoggerContext)LoggerFactory.getILoggerFactory(); + Logger logger = lc.getLogger(ConfidentialClient.class); + + // fortunately Logback already comes with a simple appender + // that just adds logs to a list. + ListAppender listAppender = new ListAppender<>(); + listAppender.setContext(lc); + listAppender.start(); + + Level previousLevel = logger.getLevel(); + logger.addAppender(listAppender); + logger.setLevel(Level.TRACE); + + try { + test.run(); + } catch (Exception e) { + throw new RuntimeException(e); + } finally { + logger.detachAppender(listAppender); + logger.setLevel(previousLevel); + listAppender.stop(); + } + + return assertThat(listAppender.list); + } + + private static ListAssert assertThatLogs( + Class expectedException, ThrowingRunnable test) + { + return assertThatLogs(() -> assertThrows(expectedException, test::run)); + } + + interface ThrowingRunnable + { + void run() throws Exception; + } + +} diff --git a/src/test/java/com/factset/sdk/utils/authentication/ConfidentialClientTest.java b/src/test/java/com/factset/sdk/utils/authentication/ConfidentialClientTest.java index 448c093..19d4efb 100644 --- a/src/test/java/com/factset/sdk/utils/authentication/ConfidentialClientTest.java +++ b/src/test/java/com/factset/sdk/utils/authentication/ConfidentialClientTest.java @@ -24,26 +24,25 @@ class ConfidentialClientTest { - private static String validJwk; + public final static String validJwk = "{\n" + + " \"p\": \"3QAUkyFNCv8CRLQfpj9zovNUchcN-HgCxOY_BMWPsbFzZ8slliFoQl8EANEJJPUMKY8sh3ZnU0pH2T8qoQoRvDstX4XzH0kdMKK8LMJ-8J5Nzf2Ps9Z2va_G0OhkMkdT__7jzO-qHQAgIxOy15ka4JGvqhi9fsB13RslsRNOpnk\",\n" + + " \"kty\": \"RSA\",\n" + + " \"q\": \"oBZ17ZrK2B5ufELRwc3ZLB09xo2LjuEK7k8ZTtM5FUBTn-6hoaJwwyJvI5UgxY5Ge46i_wQifMOJb3g-ALu8pq-Nm6N0HmZ9dxU8_REZEQFARM9pieU-dQxYJZFrbqWFLiVYc8kq8mocQe25TFmBI3t_TQ8Y7C2KltOKQTbnkAs\",\n" + + " \"d\": \"eeZ7uLCCq9Xzd6q0O13F38hfGEgajV_zMf893Bm-qjH3ipzwCztESeqaKJFNmZEkQ1a2ee2Rvjt0yZLF-8Fxu53TgfEipNWF03zraEhmM62wf86g1dFrAwFBJ0-HbPyQ_Z9zvD8y_XjrxNJ887bxHJmnFU1ER2AfW519mHm2zH8mU_tZQrhQ3f8bJSkg528LDSmStCXUPHKczxdCQj5Vg93mZQtHFG-r3h0AHWZKIidDqoFZTNuimrFL-BTAiT72GnFDhJTKpzGnWXeQ65e_0z0agh2hHYTNyKcTffWjRnNwH5q02VpHLHQ_I8GFGmhzdN4Mtg9tVQ_dpOiOiaw-UQ\",\n" + + " \"e\": \"AQAB\",\n" + + " \"use\": \"sig\",\n" + + " \"kid\": \"Pa-A4WppSTO39nfRFBP_IpM13sBNXnmj9liYF5pYRhI\",\n" + + " \"qi\": \"tBOoQVBu032Lkpnv5z5I4ynNhW8wD5o8DzMyH6OOeFujTz83plsk8zwZiKnSKcL2Qx9eUgmcLGMlx30lkyaw0nkHB7P6WDXqXsrS1c69ninzkzHd32-tQpqrOMT8vQKa0tawZjrIaEoR-3MhbMOXYrNCZvuixdJXz2E4KrJsFN0\",\n" + + " \"dp\": \"tbb-M-ga0CLUO6ebqnfb3i2Tzuez_gy3wizLvmGvgF03Vi3MbwBzGLfFs-ItUa0H3hgydgPee7bFExWEOLvtz0cdTMD4Ik5c6QO2FFusQq73rJuEEEwUgG3K3TVoRYsuv3xW1MhvqL7UreLhl7L1TZecyBDlpxYbE73hpRMKBYk\",\n" + + " \"alg\": \"RS256\",\n" + + " \"dq\": \"QzGqRhUW1yfO0DFrwaEZar7LUy_OSCaFZAmnYcKezyC0-Qg8p497LSyi4ZiSrNlPFEWGfOvLXfrlEPizbbNfN8ev9IfjEW-LchRkCQTINK8FvtwgPFUQpiiMRxiGs2aeRARA4Dir4hxPyAx0HmvjHHWVtU6E830aEryv5zeYcok\",\n" + + " \"n\": \"ijNwq-GQdu9yj1fpCLF3LJeKD_KxCFdVR6s4N57eNuhfZKGwQrnc_kf_1j7VLPCHx-UVI-S4A2yUKlo-G6h2otpQUtoN9WYaSIrowo2k7Fdd55zW1rtNzD_XplWLc8ZnBrGHLfWAQfMDHvhHsuPVctt3uH1aIv768iWahALra-ym0HHge_mluCD823Ovam-q_sn50ZCf58DbecZj7VGVCkzRNLDJsnSvh3w7BHDwUhw_oZls75IfZ-ORZQuykfEDvaHCrNbHaKJFK843m9v5C47BGqjTEqBOQ71XR3oZ-Znr1nlcE8k1FlkgA3VCFWFZuixEQJtg1tiKqbtGzzQ3Mw\"\n" + + "}"; + private static Path pathToResources; @BeforeAll static void setup() { - validJwk = "{\n" + - " \"p\": \"3QAUkyFNCv8CRLQfpj9zovNUchcN-HgCxOY_BMWPsbFzZ8slliFoQl8EANEJJPUMKY8sh3ZnU0pH2T8qoQoRvDstX4XzH0kdMKK8LMJ-8J5Nzf2Ps9Z2va_G0OhkMkdT__7jzO-qHQAgIxOy15ka4JGvqhi9fsB13RslsRNOpnk\",\n" + - " \"kty\": \"RSA\",\n" + - " \"q\": \"oBZ17ZrK2B5ufELRwc3ZLB09xo2LjuEK7k8ZTtM5FUBTn-6hoaJwwyJvI5UgxY5Ge46i_wQifMOJb3g-ALu8pq-Nm6N0HmZ9dxU8_REZEQFARM9pieU-dQxYJZFrbqWFLiVYc8kq8mocQe25TFmBI3t_TQ8Y7C2KltOKQTbnkAs\",\n" + - " \"d\": \"eeZ7uLCCq9Xzd6q0O13F38hfGEgajV_zMf893Bm-qjH3ipzwCztESeqaKJFNmZEkQ1a2ee2Rvjt0yZLF-8Fxu53TgfEipNWF03zraEhmM62wf86g1dFrAwFBJ0-HbPyQ_Z9zvD8y_XjrxNJ887bxHJmnFU1ER2AfW519mHm2zH8mU_tZQrhQ3f8bJSkg528LDSmStCXUPHKczxdCQj5Vg93mZQtHFG-r3h0AHWZKIidDqoFZTNuimrFL-BTAiT72GnFDhJTKpzGnWXeQ65e_0z0agh2hHYTNyKcTffWjRnNwH5q02VpHLHQ_I8GFGmhzdN4Mtg9tVQ_dpOiOiaw-UQ\",\n" + - " \"e\": \"AQAB\",\n" + - " \"use\": \"sig\",\n" + - " \"kid\": \"Pa-A4WppSTO39nfRFBP_IpM13sBNXnmj9liYF5pYRhI\",\n" + - " \"qi\": \"tBOoQVBu032Lkpnv5z5I4ynNhW8wD5o8DzMyH6OOeFujTz83plsk8zwZiKnSKcL2Qx9eUgmcLGMlx30lkyaw0nkHB7P6WDXqXsrS1c69ninzkzHd32-tQpqrOMT8vQKa0tawZjrIaEoR-3MhbMOXYrNCZvuixdJXz2E4KrJsFN0\",\n" + - " \"dp\": \"tbb-M-ga0CLUO6ebqnfb3i2Tzuez_gy3wizLvmGvgF03Vi3MbwBzGLfFs-ItUa0H3hgydgPee7bFExWEOLvtz0cdTMD4Ik5c6QO2FFusQq73rJuEEEwUgG3K3TVoRYsuv3xW1MhvqL7UreLhl7L1TZecyBDlpxYbE73hpRMKBYk\",\n" + - " \"alg\": \"RS256\",\n" + - " \"dq\": \"QzGqRhUW1yfO0DFrwaEZar7LUy_OSCaFZAmnYcKezyC0-Qg8p497LSyi4ZiSrNlPFEWGfOvLXfrlEPizbbNfN8ev9IfjEW-LchRkCQTINK8FvtwgPFUQpiiMRxiGs2aeRARA4Dir4hxPyAx0HmvjHHWVtU6E830aEryv5zeYcok\",\n" + - " \"n\": \"ijNwq-GQdu9yj1fpCLF3LJeKD_KxCFdVR6s4N57eNuhfZKGwQrnc_kf_1j7VLPCHx-UVI-S4A2yUKlo-G6h2otpQUtoN9WYaSIrowo2k7Fdd55zW1rtNzD_XplWLc8ZnBrGHLfWAQfMDHvhHsuPVctt3uH1aIv768iWahALra-ym0HHge_mluCD823Ovam-q_sn50ZCf58DbecZj7VGVCkzRNLDJsnSvh3w7BHDwUhw_oZls75IfZ-ORZQuykfEDvaHCrNbHaKJFK843m9v5C47BGqjTEqBOQ71XR3oZ-Znr1nlcE8k1FlkgA3VCFWFZuixEQJtg1tiKqbtGzzQ3Mw\"\n" + - "}"; - pathToResources = Paths.get(System.getProperty("user.dir"), "src", "test", "resources"); } diff --git a/src/test/resources/logback-test.xml b/src/test/resources/logback-test.xml new file mode 100644 index 0000000..3031276 --- /dev/null +++ b/src/test/resources/logback-test.xml @@ -0,0 +1,15 @@ + + + + %d{ISO8601} [%thread] %-5level %logger{36} - %msg%n + + + + + + + + + + + diff --git a/src/test/resources/well-known-uri-response.json b/src/test/resources/well-known-uri-response.json new file mode 100644 index 0000000..bc597f7 --- /dev/null +++ b/src/test/resources/well-known-uri-response.json @@ -0,0 +1,37 @@ +{ + "issuer": "https://example.com", + "authorization_endpoint": "https://example.com/as/authorization.oauth2", + "token_endpoint": "https://example.com/as/token.oauth2", + "revocation_endpoint": "https://example.com/as/revoke_token.oauth2", + "userinfo_endpoint": "https://example.com/idp/userinfo.openid", + "introspection_endpoint": "https://example.com/as/introspect.oauth2", + "jwks_uri": "https://example.com/pf/JWKS", + "registration_endpoint": "https://example.com/as/clients.oauth2", + "ping_revoked_sris_endpoint": "https://example.com/pf-ws/rest/sessionMgmt/revokedSris", + "ping_session_management_sris_endpoint": "https://example.com/pf-ws/rest/sessionMgmt/sessions", + "ping_end_session_endpoint": "https://example.com/idp/startSLO.ping", + "device_authorization_endpoint": "https://example.com/as/device_authz.oauth2", + "scopes_supported": [ "openid" ], + "claims_supported": [ "serial", "sub", "trustzone", "username" ], + "response_types_supported": [ "code", "token", "id_token", "code token", "code id_token", "token id_token", "code token id_token" ], + "response_modes_supported": [ "fragment", "query", "form_post" ], + "grant_types_supported": [ "implicit", "authorization_code", "refresh_token", "password", "client_credentials", "urn:pingidentity.com:oauth2:grant_type:validate_bearer", "urn:ietf:params:oauth:grant-type:jwt-bearer", "urn:ietf:params:oauth:grant-type:saml2-bearer", "urn:ietf:params:oauth:grant-type:device_code", "urn:ietf:params:oauth:grant-type:token-exchange", "urn:openid:params:grant-type:ciba" ], + "subject_types_supported": [ "public", "pairwise" ], + "id_token_signing_alg_values_supported": [ "none", "HS256", "HS384", "HS512", "RS256", "RS384", "RS512", "ES256", "ES384", "ES512", "PS256", "PS384", "PS512" ], + "token_endpoint_auth_methods_supported": [ "client_secret_basic", "client_secret_post", "private_key_jwt" ], + "token_endpoint_auth_signing_alg_values_supported": [ "RS256", "RS384", "RS512", "ES256", "ES384", "ES512", "PS256", "PS384", "PS512" ], + "claim_types_supported": [ "normal" ], + "claims_parameter_supported": false, + "request_parameter_supported": true, + "request_uri_parameter_supported": false, + "request_object_signing_alg_values_supported": [ "RS256", "RS384", "RS512", "ES256", "ES384", "ES512", "PS256", "PS384", "PS512" ], + "id_token_encryption_alg_values_supported": [ "dir", "A128KW", "A192KW", "A256KW", "A128GCMKW", "A192GCMKW", "A256GCMKW", "ECDH-ES", "ECDH-ES+A128KW", "ECDH-ES+A192KW", "ECDH-ES+A256KW", "RSA-OAEP" ], + "id_token_encryption_enc_values_supported": [ "A128CBC-HS256", "A192CBC-HS384", "A256CBC-HS512", "A128GCM", "A192GCM", "A256GCM" ], + "pushed_authorization_request_endpoint": "https://example.com/as/par.oauth2", + "require_pushed_authorization_requests": false, + "backchannel_authentication_endpoint": "https://example.com/as/bc-auth.ciba", + "backchannel_token_delivery_modes_supported": [ "poll", "ping" ], + "backchannel_authentication_request_signing_alg_values_supported": [ "RS256", "RS384", "RS512", "ES256", "ES384", "ES512", "PS256", "PS384", "PS512" ], + "backchannel_user_code_parameter_supported": false, + "code_challenge_methods_supported": [ "plain", "S256" ] +}