factset · Erik Schmidt (eschmidtfds) · Aug 16, 2022 · Aug 3, 2022
@@ -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

@@ -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) {

@@ -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 {

@@ -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<ILoggingEvent> 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<ILoggingEvent> 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 <T extends Throwable> ListAssert<ILoggingEvent> assertThatLogs(
+        Class<T> expectedException, ThrowingRunnable test)
+    {
+        return assertThatLogs(() -> assertThrows(expectedException, test::run));
+    }
+
+    interface ThrowingRunnable
+    {
+        void run() throws Exception;
+    }
+
+}
@@ -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");
     }
 

@@ -0,0 +1,15 @@
+<configuration>
+  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
+    <encoder>
+      <pattern>%d{ISO8601} [%thread] %-5level %logger{36} - %msg%n</pattern>
+    </encoder>
+  </appender>
+
+  <appender name="NOP" class="ch.qos.logback.core.helpers.NOPAppender" />
+
+  <root level="OFF">
+    <!-- replace with STDOUT to see logs locally -->
+    <appender-ref ref="NOP" />
+  </root>
+  <logger name="wiremock" level="ERROR"/>
+</configuration>
@@ -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" ]
+}