I cloned https://github.com/cloudfoundry/uaa, ran the server locally to test an authorization code flow.
I'm getting a strange InvalidClientException, Client ID mismatch error when trying to exchange an authorization code for a token.
My client is defined like this:
#!/bin/bash
uaac client delete cfbrowser
uaac client add cfbrowser -s exploradorcf\
--authorities uaa.none\
--authorized_grant_types authorization_code\
--scope 'uaa.user cloud_controller.read cloud_controller.write\
openid password.write scim.userids cloud_controller.admin scim.read scim.write'\
--redirect_uri "http://localhost:1223/oauth/code-grant"
I can use the following curl command to successfully obtain a token, note this is using built-in client login:
curl 'http://localhost:8080/uaa/oauth/token' -i -X POST -H 'Accept: application/json'\
-H 'Content-Type: application/x-www-form-urlencoded' \
-d 'client_id=login&client_secret=loginsecret&grant_type=authorization_code&response_type=token&token_format=opaque&redirect_uri=http%3A%2F%2Flocalhost%3A1223%2Foauth%2Fcode-grant&code=nL3MPz'
HTTP/1.1 200 OK
Server: Apache-Coyote/1.1
Cache-Control: no-store
Pragma: no-cache
X-XSS-Protection: 1; mode=block
X-Frame-Options: DENY
X-Content-Type-Options: nosniff
Content-Type: application/json;charset=UTF-8
Transfer-Encoding: chunked
Date: Wed, 10 Aug 2016 17:50:27 GMT
{"access_token":"206f1b38e6ee4cbe9ace51038a4a70ad","token_type":"bearer","refresh_token":"206f1b38e6ee4cbe9ace51038a4a70ad-r","expires_in":43199,"scope":"openid oauth.approvals","jti":"206f1b38e6ee4cbe9ace51038a4a70ad"}
If I change the client_id and client_secret:
curl 'http://localhost:8080/uaa/oauth/token' -i -X POST -H 'Accept: application/json'\
-H 'Content-Type: application/x-www-form-urlencoded' \
-d 'client_id=cfbrowser&client_secret=exploradorcf&grant_type=authorization_code&response_type=token&token_format=opaque&redirect_uri=http%3A%2F%2Flocalhost%3A1223%2Foauth%2Fcode-grant&code=nL3MPz'
I get "Client ID mismatch"
HTTP/1.1 401 Unauthorized
Server: Apache-Coyote/1.1
Cache-Control: no-store
Pragma: no-cache
WWW-Authenticate: Bearer error="invalid_client", error_description="Client ID mismatch"
X-XSS-Protection: 1; mode=block
X-Frame-Options: DENY
X-Content-Type-Options: nosniff
Content-Type: application/json;charset=UTF-8
Transfer-Encoding: chunked
Date: Wed, 10 Aug 2016 18:04:17 GMT
{"error":"invalid_client","error_description":"Client ID mismatch"}
Looking at the uaa-server.log logs, I can see:
[2016-08-10 22:44:42.493] cloudfoundry-identity-server - ???? [http-nio-8080-exec-8] .... DEBUG --- UaaRequestMatcher: [loginAuthenticateRequestMatcher] Checking match of request : '/uaa/oauth/authorize'; '/uaa/authenticate' with parameters={} and headers {Authorization=[bearer ], accept=[application/json]}
[2016-08-10 22:44:42.493] cloudfoundry-identity-server - ???? [http-nio-8080-exec-8] .... DEBUG --- UaaRequestMatcher: [loginAuthorizeRequestMatcher] Checking match of request : '/uaa/oauth/authorize'; '/uaa/oauth/authorize' with parameters={source=login} and headers {accept=[application/json]}
[2016-08-10 22:44:42.494] cloudfoundry-identity-server - ???? [http-nio-8080-exec-8] .... DEBUG --- UaaRequestMatcher: [loginTokenRequestMatcher] Checking match of request : '/uaa/oauth/authorize'; '/uaa/oauth/token' with parameters={source=login, grant_type=password, add_new=} and headers {Authorization=[bearer ], accept=[application/json]}
[2016-08-10 22:44:42.494] cloudfoundry-identity-server - ???? [http-nio-8080-exec-8] .... DEBUG --- UaaRequestMatcher: [loginAuthorizeRequestMatcherOld] Checking match of request : '/uaa/oauth/authorize'; '/uaa/oauth/authorize' with parameters={login={} and headers {accept=[application/json]}
[2016-08-10 22:44:42.494] cloudfoundry-identity-server - ???? [http-nio-8080-exec-8] .... DEBUG --- UaaRequestMatcher: [passcodeTokenMatcher] Checking match of request : '/uaa/oauth/authorize'; '/uaa/oauth/token' with parameters={grant_type=password, passcode=} and headers {accept=[application/json, application/x-www-form-urlencoded]}
[2016-08-10 22:44:42.494] cloudfoundry-identity-server - ???? [http-nio-8080-exec-8] .... DEBUG --- UaaRequestMatcher: [oauthAuthorizeRequestMatcher] Checking match of request : '/uaa/oauth/authorize'; '/uaa/oauth/authorize' with parameters={response_type=token, source=credentials} and headers {accept=[application/json, application/x-www-form-urlencoded]}
[2016-08-10 22:44:42.494] cloudfoundry-identity-server - ???? [http-nio-8080-exec-8] .... DEBUG --- UaaRequestMatcher: [oauthAuthorizeApiRequestMatcher] Checking match of request : '/uaa/oauth/authorize'; '/uaa/oauth/authorize' with parameters={response_type=code, client_id=} and headers {Authorization=[bearer ]}
[2016-08-10 22:44:42.494] cloudfoundry-identity-server - ???? [http-nio-8080-exec-8] .... DEBUG --- UaaRequestMatcher: [xOauthCallbackRequestMatcher] Checking match of request : '/uaa/oauth/authorize'; '/uaa/login/callback' with parameters={code=} and headers {}
[2016-08-10 22:44:42.495] cloudfoundry-identity-server - ???? [http-nio-8080-exec-8] .... DEBUG --- UaaRequestMatcher: [oauthAuthorizeRequestMatcherOld] Checking match of request : '/uaa/oauth/authorize'; '/uaa/oauth/authorize' with parameters={response_type=token, credentials={} and headers {accept=[application/json, application/x-www-form-urlencoded]}
[2016-08-10 22:44:42.495] cloudfoundry-identity-server - ???? [http-nio-8080-exec-8] .... DEBUG --- UaaRequestMatcher: [autologinAuthorizeRequestMatcher] Checking match of request : '/uaa/oauth/authorize'; '/uaa/oauth/authorize' with parameters={response_type=code, code=} and headers {}
[2016-08-10 22:44:42.495] cloudfoundry-identity-server - ???? [http-nio-8080-exec-8] .... DEBUG --- UaaRequestMatcher: [autologinRequestMatcher] Checking match of request : '/uaa/oauth/authorize'; '/uaa/autologin' with parameters={code=} and headers {}
[2016-08-10 22:44:42.499] cloudfoundry-identity-server - ???? [http-nio-8080-exec-8] .... DEBUG --- DisableIdTokenResponseTypeFilter: Processing id_token disable filter
[2016-08-10 22:44:42.499] cloudfoundry-identity-server - ???? [http-nio-8080-exec-8] .... DEBUG --- DisableIdTokenResponseTypeFilter: pre id_token disable:false pathinfo:null request_uri:/uaa/oauth/authorize response_type:code
[2016-08-10 22:44:42.499] cloudfoundry-identity-server - ???? [http-nio-8080-exec-8] .... DEBUG --- DisableIdTokenResponseTypeFilter: post id_token disable:false pathinfo:null request_uri:/uaa/oauth/authorize response_type:code
[2016-08-10 22:44:42.500] cloudfoundry-identity-server - ???? [http-nio-8080-exec-8] .... DEBUG --- SecurityFilterChainPostProcessor$HttpsEnforcementFilter: Filter chain 'uiSecurity' processing request GET /uaa/oauth/authorize
[2016-08-10 22:44:42.500] cloudfoundry-identity-server - ???? [http-nio-8080-exec-8] .... DEBUG --- SessionResetFilter: Evaluating user-id for session reset:a6350566-abd3-4cc5-89e5-5cd83a5f0d70
[2016-08-10 22:44:42.513] cloudfoundry-identity-server - ???? [http-nio-8080-exec-8] .... DEBUG --- UserManagedAuthzApprovalHandler: Looking up user approved authorizations for client_id=login and username=marissa
[2016-08-10 22:44:42.515] cloudfoundry-identity-server - ???? [http-nio-8080-exec-8] .... DEBUG --- JdbcApprovalStore: Filtering approvals with filter: [sql: (LOWER(user_id) = LOWER(:__wnq8ah_0) AND LOWER(client_id) = LOWER(:__wnq8ah_1)), params: {__wnq8ah_1=login, __wnq8ah_0=a6350566-abd3-4cc5-89e5-5cd83a5f0d70}]
[2016-08-10 22:44:42.516] cloudfoundry-identity-server - ???? [http-nio-8080-exec-8] .... DEBUG --- UserManagedAuthzApprovalHandler: Valid user approved/denied scopes are [openid, oauth.approvals]
[2016-08-10 22:44:42.518] cloudfoundry-identity-server - ???? [http-nio-8080-exec-8] .... DEBUG --- UaaTokenStore: [oauth_code] Removed 0 expired entries.
[2016-08-10 22:44:42.519] cloudfoundry-identity-server - ???? [http-nio-8080-exec-8] .... DEBUG --- UaaTokenStore: [oauth_code] Removed 0 old entries.
[2016-08-10 22:44:42.570] cloudfoundry-identity-server - ???? [http-nio-8080-exec-9] .... DEBUG --- UaaRequestMatcher: [loginAuthenticateRequestMatcher] Checking match of request : '/uaa/oauth/token'; '/uaa/authenticate' with parameters={} and headers {Authorization=[bearer ], accept=[application/json]}
[2016-08-10 22:44:42.570] cloudfoundry-identity-server - ???? [http-nio-8080-exec-9] .... DEBUG --- UaaRequestMatcher: [loginAuthorizeRequestMatcher] Checking match of request : '/uaa/oauth/token'; '/uaa/oauth/authorize' with parameters={source=login} and headers {accept=[application/json]}
[2016-08-10 22:44:42.571] cloudfoundry-identity-server - ???? [http-nio-8080-exec-9] .... DEBUG --- UaaRequestMatcher: [loginTokenRequestMatcher] Checking match of request : '/uaa/oauth/token'; '/uaa/oauth/token' with parameters={source=login, grant_type=password, add_new=} and headers {Authorization=[bearer ], accept=[application/json]}
[2016-08-10 22:44:42.571] cloudfoundry-identity-server - ???? [http-nio-8080-exec-9] .... DEBUG --- UaaRequestMatcher: [loginAuthorizeRequestMatcherOld] Checking match of request : '/uaa/oauth/token'; '/uaa/oauth/authorize' with parameters={login={} and headers {accept=[application/json]}
[2016-08-10 22:44:42.571] cloudfoundry-identity-server - ???? [http-nio-8080-exec-9] .... DEBUG --- UaaRequestMatcher: [passcodeTokenMatcher] Checking match of request : '/uaa/oauth/token'; '/uaa/oauth/token' with parameters={grant_type=password, passcode=} and headers {accept=[application/json, application/x-www-form-urlencoded]}
[2016-08-10 22:44:42.573] cloudfoundry-identity-server - ???? [http-nio-8080-exec-9] .... DEBUG --- DisableIdTokenResponseTypeFilter: Processing id_token disable filter
[2016-08-10 22:44:42.573] cloudfoundry-identity-server - ???? [http-nio-8080-exec-9] .... DEBUG --- DisableIdTokenResponseTypeFilter: pre id_token disable:false pathinfo:null request_uri:/uaa/oauth/token response_type:token
[2016-08-10 22:44:42.574] cloudfoundry-identity-server - ???? [http-nio-8080-exec-9] .... DEBUG --- DisableIdTokenResponseTypeFilter: post id_token disable:false pathinfo:null request_uri:/uaa/oauth/token response_type:token
[2016-08-10 22:44:42.574] cloudfoundry-identity-server - ???? [http-nio-8080-exec-9] .... DEBUG --- SecurityFilterChainPostProcessor$HttpsEnforcementFilter: Filter chain 'tokenEndpointSecurity' processing request POST /uaa/oauth/token
[2016-08-10 22:44:42.575] cloudfoundry-identity-server - ???? [http-nio-8080-exec-9] .... INFO --- Audit: ClientAuthenticationSuccess ('Client authentication success'): principal=cfbrowser, origin=[remoteAddress=127.0.0.1, clientId=cfbrowser], identityZoneId=[uaa]
[2016-08-10 22:44:42.585] cloudfoundry-identity-server - ???? [http-nio-8080-exec-9] .... DEBUG --- UaaTokenStore: [oauth_code] Removed 0 expired entries.
[2016-08-10 22:44:42.586] cloudfoundry-identity-server - ???? [http-nio-8080-exec-9] .... DEBUG --- UaaTokenStore: [oauth_code] Removed 0 old entries.
[2016-08-10 22:44:42.589] cloudfoundry-identity-server - ???? [http-nio-8080-exec-9] .... INFO --- TokenEndpoint: Handling error: InvalidClientException, Client ID mismatch
So I don't see anything wrong with the client id from the logs.
Comparing the 2 clients:
$ uaac client get login
scope: openid oauth.approvals
client_id: login
resource_ids: none
authorized_grant_types: client_credentials authorization_code refresh_token
autoapprove: true
authorities: clients.read emails.write scim.userids password.write idps.write
notifications.write oauth.login scim.write critical_notifications.write
lastmodified: 1470892674539
$ uaac client get cfbrowser
scope: cloud_controller.read password.write scim.userids cloud_controller.write
openid scim.write scim.read uaa.user cloud_controller.admin
client_id: cfbrowser
resource_ids: none
authorized_grant_types: authorization_code refresh_token
redirect_uri: http://localhost:1223/oauth/code-grant
autoapprove:
authorities: uaa.none
name: cfbrowser
lastmodified: 1470894239209
Doesn't tell me anything interesting.
code:
if (clientId != null && !clientId.equals(unconfirmedAuthorizationRequest.getClientId())) {
// just a sanity check.
throw new InvalidClientException("Client ID mismatch");
}
So I tried cloning and building that project to mvn install locally, again hoping to log what is
clientId compared to unconfirmedAuthorizationRequest.getClientId(), but wasn't able to build:
I feel I've exhausted most of what I can think of for self-help. My questions are:
Why am I getting this "Client ID mismatch"?
The client id in the POST /oauth/token must be the same as the client_id in the GET /oauth/authorize. The one time code issued during /oauth/authorize, is pinned to a specific client_id, and cannot be used by another client.
What is the java source class and method producing this error and log? I think you already answered this question for yourself.
What other steps should I have taken for debugging this issue myself?
If you are a developer, and have an IDE, the easiest thing to do is to clone the project. Then simply import it into your IDE. We debug the UAA locally directly in our IntelliJ environment.