Login succeeds from login web UI but error from cf login or uaac

525 views

Skip to first unread message

m...@matt-j.co.uk

unread,

Oct 3, 2013, 10:09:48 AM10/3/13

to vcap...@cloudfoundry.org

I've been stuck on a weird issue with authentication for a couple of days. Using UAA with the SCIM builtin accounts (extract):

properties:
  uaa:
    scim:
      userids_enabled: true
      users:
      - matt|matt|scim.write,scim.read,openid,cloud_controller.admin

Deployed CF143 successfully, test the logon service via the login webui.

uaa.log output from /var/vcap/sys/log/uaa/ for web login through login service stock ui:

[2013-10-03 13:32:49.354] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/authenticate'; against '/resources/**'
[2013-10-03 13:32:49.354] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/authenticate'; against '/favicon.ico'
[2013-10-03 13:32:49.354] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/authenticate'; against '/info'
[2013-10-03 13:32:49.354] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/authenticate'; against '/password/**'
[2013-10-03 13:32:49.354] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/authenticate'; against '/healthz/**'
[2013-10-03 13:32:49.354] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- UaaRequestMatcher: Checking match of request : '/authenticate'; '/oauth/token' with parameters={} and headers {authorization=[Basic ]}
[2013-10-03 13:32:49.354] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- UaaRequestMatcher: Checking match of request : '/authenticate'; '/oauth/token' with parameters={} and headers {authorization=[Bearer ]}
[2013-10-03 13:32:49.354] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- UaaRequestMatcher: Checking match of request : '/authenticate'; '/oauth/authorize' with parameters={response_type=token, source=credentials} and headers {accept=[application/json, application/x-www-form-urlencoded]}
[2013-10-03 13:32:49.354] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- UaaRequestMatcher: Checking match of request : '/authenticate'; '/oauth/authorize' with parameters={response_type=token, credentials={} and headers {accept=[application/json, application/x-www-form-urlencoded]}
[2013-10-03 13:32:49.354] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/authenticate'; against '/authenticate/**'
[2013-10-03 13:32:49.354] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- FilterChainProxy: /authenticate at position 1 of 1 in additional filter chain; firing Filter: 'UaaLoggingFilter'
[2013-10-03 13:32:49.354] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- SecurityFilterChainPostProcessor$UaaLoggingFilter: Filter chain 'org.springframework.security.web.DefaultSecurityFilterChain#5' processing request POST /authenticate
[2013-10-03 13:32:49.354] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- FilterChainProxy: /authenticate reached end of additional filter chain; proceeding with original chain
[2013-10-03 13:32:49.354] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- DispatcherServlet: DispatcherServlet with name 'spring' processing POST request for [/authenticate]
[2013-10-03 13:32:49.354] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- RequestMappingHandlerMapping: Looking up handler method for path /authenticate
[2013-10-03 13:32:49.355] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- RequestMappingHandlerMapping: Returning handler method [public org.springframework.http.HttpEntity<java.util.Map<java.lang.String, java.lang.String>> org.cloudfoundry.identity.uaa.authentication.login.RemoteAuthenticationEndpoint.authenticate(javax.servlet.http.HttpServletRequest,java.lang.String,java.lang.String)]
[2013-10-03 13:32:49.356] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AuthzAuthenticationManager: Processing authentication request for matt
[2013-10-03 13:32:49.356] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-10-03 13:32:49.356] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select id,username,password,email,givenName,familyName,created,lastModified from users where lower(username) = ? and active=?]
[2013-10-03 13:32:49.356] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- DataSourceUtils: Fetching JDBC Connection from DataSource
[2013-10-03 13:32:49.357] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-10-03 13:32:49.357] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select g.displayName from groups g, group_membership m where g.id = m.group_id and m.member_id = ?]
[2013-10-03 13:32:49.357] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- DataSourceUtils: Fetching JDBC Connection from DataSource
[2013-10-03 13:32:49.358] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- DataSourceUtils: Returning JDBC Connection to DataSource
[2013-10-03 13:32:49.358] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- DataSourceUtils: Returning JDBC Connection to DataSource
[2013-10-03 13:32:49.501] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-10-03 13:32:49.501] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select event_type, principal_id, origin, event_data, created from sec_audit where principal_id=? and created > ? order by created desc]
[2013-10-03 13:32:49.501] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- DataSourceUtils: Fetching JDBC Connection from DataSource
[2013-10-03 13:32:49.502] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- DataSourceUtils: Returning JDBC Connection to DataSource
[2013-10-03 13:32:49.502] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AuthzAuthenticationManager: Password successfully matched
[2013-10-03 13:32:49.502] uaa - 8519 [http-bio-80-exec-5] ....  INFO --- Audit: UserAuthenticationSuccess ('matt'): principal=186676e2-d9c4-4074-b395-55868a1f9168, origin=[remoteAddress=9.10.7.205]
[2013-10-03 13:32:49.503] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- JdbcTemplate: Executing prepared SQL update
[2013-10-03 13:32:49.503] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [delete from sec_audit where principal_id=?]
[2013-10-03 13:32:49.503] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- DataSourceUtils: Fetching JDBC Connection from DataSource
[2013-10-03 13:32:49.503] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- JdbcTemplate: SQL update affected 0 rows
[2013-10-03 13:32:49.503] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- DataSourceUtils: Returning JDBC Connection to DataSource
[2013-10-03 13:32:49.504] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- HttpEntityMethodProcessor: Written [{username=matt}] as "application/json;charset=UTF-8" using [org.springframework.http.converter.json.MappingJacksonHttpMessageConverter@155ec9f4]
[2013-10-03 13:32:49.504] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- DispatcherServlet: Null ModelAndView returned to DispatcherServlet with name 'spring': assuming HandlerAdapter completed request handling
[2013-10-03 13:32:49.504] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- DispatcherServlet: Successfully completed request

Happy logon!

Now I try cf target and login with the same credentials (matt/matt) and also my admin user, both get a weird output back;

matt@matjohn2-mac cf-install (bxbft2) $ cf target https://api.int.ft1.cpgpaas.net
Setting target to https://api.int.ft1.cpgpaas.net... OK
matt@matjohn2-mac cf-install (bxbft2) $ cf login
target: https://api.int.ft1.cpgpaas.net

Email> matt

Password> ****

Authenticating... OK

Invalid authentication token. Try logging in again with 'cf login'. If problems continue, please contact your Cloud Operator.
matt@matjohn2-mac cf-install (bxbft2) $ cf login
target: https://api.int.ft1.cpgpaas.net

Email> admin

Password> ***********

Authenticating... OK

Invalid authentication token. Try logging in again with 'cf login'. If problems continue, please contact your Cloud Operator.
matt@matjohn2-mac cf-install (bxbft2) $

Compared to a non-existant user;

matt@matjohn2-mac cf-install (bxbft2) $ cf login
target: https://api.int.ft1.cpgpaas.net


Email> nonexistant


Password> ****


Authenticating... FAILED

The UAA logs for my 'valid' user used to show 'authentication failed' which didn't make sense, because the UI logon above worked fine.

However then i found this post: https://groups.google.com/a/cloudfoundry.org/forum/#!msg/vcap-dev/mReKiNP7H6A/aMxPG8eJTZsJ

Which suggested that my db_schema: properties could be wrong for uaadb and ccdb.

After a lot of messing (i suspect these properties didn't take effect unless the vm was rebuilt) and looking through the cf-release github in frustration, It seems;

cloud controller DB's need;

db_scheme: postgres

UAA DB's need;

db_scheme: postgresql

+1 for conformity ;)

(And yes, the perfectly timed github DDoS co-incided with this... typical!)

So after destroying the uaadb, ccdb, cloud_controller and uaa jobs and re-adding them, with the properties for each set to one of the two db_scheme's as above... I now get authentication success in the UAA log (Below).

However I'm still getting the strange error in cf login;

target: https://api.int.ft1.cpgpaas.net
Email> matt
Password> ****
Authenticating... OK
Invalid authentication token. Try logging in again with 'cf login'. If problems continue, please contact your Cloud Operator.

[2013-10-03 13:45:08.603] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/resources/**'
[2013-10-03 13:45:08.603] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/favicon.ico'
[2013-10-03 13:45:08.603] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/info'
[2013-10-03 13:45:08.603] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/password/**'
[2013-10-03 13:45:08.604] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/healthz/**'
[2013-10-03 13:45:08.604] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- UaaRequestMatcher: Checking match of request : '/login'; '/oauth/token' with parameters={} and headers {authorization=[Basic ]}
[2013-10-03 13:45:08.604] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- UaaRequestMatcher: Checking match of request : '/login'; '/oauth/token' with parameters={} and headers {authorization=[Bearer ]}
[2013-10-03 13:45:08.604] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- UaaRequestMatcher: Checking match of request : '/login'; '/oauth/authorize' with parameters={response_type=token, source=credentials} and headers {accept=[application/json, application/x-www-form-urlencoded]}
[2013-10-03 13:45:08.604] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- UaaRequestMatcher: Checking match of request : '/login'; '/oauth/authorize' with parameters={response_type=token, credentials={} and headers {accept=[application/json, application/x-www-form-urlencoded]}
[2013-10-03 13:45:08.604] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/authenticate/**'
[2013-10-03 13:45:08.604] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- UaaRequestMatcher: Checking match of request : '/login'; '/oauth/authorize' with parameters={source=login} and headers {accept=[application/json]}
[2013-10-03 13:45:08.604] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- UaaRequestMatcher: Checking match of request : '/login'; '/oauth/authorize' with parameters={login={} and headers {accept=[application/json]}
[2013-10-03 13:45:08.604] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- UaaRequestMatcher: Checking match of request : '/login'; '/Groups' with parameters={} and headers {accept=[application/json]}
[2013-10-03 13:45:08.604] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- UaaRequestMatcher: Checking match of request : '/login'; '/Groups' with parameters={} and headers {}
[2013-10-03 13:45:08.604] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/groups/**'
[2013-10-03 13:45:08.604] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/user*/*/password'
[2013-10-03 13:45:08.604] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/users/**'
[2013-10-03 13:45:08.604] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/ids/users*'
[2013-10-03 13:45:08.604] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/approvals'
[2013-10-03 13:45:08.604] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/oauth/clients/*/secret'
[2013-10-03 13:45:08.604] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/oauth/clients/**'
[2013-10-03 13:45:08.604] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/check_token'
[2013-10-03 13:45:08.604] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/token_key'
[2013-10-03 13:45:08.604] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/clientinfo'
[2013-10-03 13:45:08.605] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/userinfo'
[2013-10-03 13:45:08.605] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/'
[2013-10-03 13:45:08.605] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/spring_security_login'
[2013-10-03 13:45:08.605] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/oauth/**'
[2013-10-03 13:45:08.605] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/login**'
[2013-10-03 13:45:08.605] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- FilterChainProxy: /login at position 1 of 10 in additional filter chain; firing Filter: 'UaaLoggingFilter'
[2013-10-03 13:45:08.605] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- SecurityFilterChainPostProcessor$UaaLoggingFilter: Filter chain 'uiSecurity' processing request GET /login
[2013-10-03 13:45:08.605] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- FilterChainProxy: /login at position 2 of 10 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
[2013-10-03 13:45:08.605] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- HttpSessionSecurityContextRepository: No HttpSession currently exists
[2013-10-03 13:45:08.605] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- HttpSessionSecurityContextRepository: No SecurityContext was available from the HttpSession: null. A new one will be created.
[2013-10-03 13:45:08.605] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- FilterChainProxy: /login at position 3 of 10 in additional filter chain; firing Filter: 'LogoutFilter'
[2013-10-03 13:45:08.605] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- FilterChainProxy: /login at position 4 of 10 in additional filter chain; firing Filter: 'UsernamePasswordAuthenticationFilter'
[2013-10-03 13:45:08.605] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- FilterChainProxy: /login at position 5 of 10 in additional filter chain; firing Filter: 'RequestCacheAwareFilter'
[2013-10-03 13:45:08.605] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- FilterChainProxy: /login at position 6 of 10 in additional filter chain; firing Filter: 'SecurityContextHolderAwareRequestFilter'
[2013-10-03 13:45:08.605] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- FilterChainProxy: /login at position 7 of 10 in additional filter chain; firing Filter: 'AnonymousAuthenticationFilter'
[2013-10-03 13:45:08.605] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AnonymousAuthenticationFilter: Populated SecurityContextHolder with anonymous token: 'org.springframework.security.authentication.AnonymousAuthenticationToken@9055c2bc: Principal: anonymousUser; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@b364: RemoteIpAddress: 9.10.7.205; SessionId: null; Granted Authorities: ROLE_ANONYMOUS'
[2013-10-03 13:45:08.605] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- FilterChainProxy: /login at position 8 of 10 in additional filter chain; firing Filter: 'SessionManagementFilter'
[2013-10-03 13:45:08.605] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- FilterChainProxy: /login at position 9 of 10 in additional filter chain; firing Filter: 'ExceptionTranslationFilter'
[2013-10-03 13:45:08.605] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- FilterChainProxy: /login at position 10 of 10 in additional filter chain; firing Filter: 'FilterSecurityInterceptor'
[2013-10-03 13:45:08.605] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/login'; against '/login**'
[2013-10-03 13:45:08.605] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- FilterSecurityInterceptor: Secure object: FilterInvocation: URL: /login; Attributes: [IS_AUTHENTICATED_ANONYMOUSLY]
[2013-10-03 13:45:08.606] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- FilterSecurityInterceptor: Previously Authenticated: org.springframework.security.authentication.AnonymousAuthenticationToken@9055c2bc: Principal: anonymousUser; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@b364: RemoteIpAddress: 9.10.7.205; SessionId: null; Granted Authorities: ROLE_ANONYMOUS
[2013-10-03 13:45:08.606] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AffirmativeBased: Voter: org.springframework.security.access.vote.RoleVoter@56ad4264, returned: 0
[2013-10-03 13:45:08.606] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- AffirmativeBased: Voter: org.springframework.security.access.vote.AuthenticatedVoter@8e1dfb1, returned: 1
[2013-10-03 13:45:08.606] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- FilterSecurityInterceptor: Authorization successful
[2013-10-03 13:45:08.606] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- FilterSecurityInterceptor: RunAsManager did not change Authentication object
[2013-10-03 13:45:08.606] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- FilterChainProxy: /login reached end of additional filter chain; proceeding with original chain
[2013-10-03 13:45:08.606] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- DispatcherServlet: DispatcherServlet with name 'spring' processing GET request for [/login]
[2013-10-03 13:45:08.606] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- RequestMappingHandlerMapping: Looking up handler method for path /login
[2013-10-03 13:45:08.606] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- RequestMappingHandlerMapping: Returning handler method [public java.lang.String org.cloudfoundry.identity.uaa.authentication.login.LoginInfoEndpoint.login(org.springframework.ui.Model,java.security.Principal)]
[2013-10-03 13:45:08.606] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- DispatcherServlet: Last-Modified value for [/login] is: -1
[2013-10-03 13:45:08.607] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- ContentNegotiatingViewResolver: Requested media types are [application/json] based on Accept header types and producible media types [*/*])
[2013-10-03 13:45:08.607] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- ContentNegotiatingViewResolver: Returning [org.springframework.web.servlet.view.json.MappingJacksonJsonView: name 'org.springframework.web.servlet.view.json.MappingJacksonJsonView#4fc0cb76'] based on requested media type 'application/json'
[2013-10-03 13:45:08.607] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- DispatcherServlet: Rendering view [org.springframework.web.servlet.view.json.MappingJacksonJsonView: name 'org.springframework.web.servlet.view.json.MappingJacksonJsonView#4fc0cb76'] in DispatcherServlet with name 'spring'
[2013-10-03 13:45:08.607] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- HttpSessionSecurityContextRepository: SecurityContext is empty or contents are anonymous - context will not be stored in HttpSession.
[2013-10-03 13:45:08.608] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- DispatcherServlet: Successfully completed request
[2013-10-03 13:45:08.608] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- ExceptionTranslationFilter: Chain processed normally
[2013-10-03 13:45:08.608] uaa - 8519 [http-bio-80-exec-5] .... DEBUG --- SecurityContextPersistenceFilter: SecurityContextHolder now cleared, as request processing completed
[2013-10-03 13:45:11.274] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/oauth/token'; against '/resources/**'
[2013-10-03 13:45:11.274] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/oauth/token'; against '/favicon.ico'
[2013-10-03 13:45:11.274] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/oauth/token'; against '/info'
[2013-10-03 13:45:11.274] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/oauth/token'; against '/password/**'
[2013-10-03 13:45:11.274] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- AntPathRequestMatcher: Checking match of request : '/oauth/token'; against '/healthz/**'
[2013-10-03 13:45:11.274] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- UaaRequestMatcher: Checking match of request : '/oauth/token'; '/oauth/token' with parameters={} and headers {authorization=[Basic ]}
[2013-10-03 13:45:11.274] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- UaaRequestMatcher: Matched request /oauth/token'; '/oauth/token' with parameters={} and headers {authorization=[Basic ]}
[2013-10-03 13:45:11.274] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- FilterChainProxy: /oauth/token at position 1 of 7 in additional filter chain; firing Filter: 'UaaLoggingFilter'
[2013-10-03 13:45:11.274] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- SecurityFilterChainPostProcessor$UaaLoggingFilter: Filter chain 'tokenEndpointSecurity' processing request POST /oauth/token
[2013-10-03 13:45:11.274] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- FilterChainProxy: /oauth/token at position 2 of 7 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
[2013-10-03 13:45:11.274] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- FilterChainProxy: /oauth/token at position 3 of 7 in additional filter chain; firing Filter: 'BasicAuthenticationFilter'
[2013-10-03 13:45:11.274] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- BasicAuthenticationFilter: Basic Authentication Authorization header found for user 'cf'
[2013-10-03 13:45:11.275] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- ProviderManager: Authentication attempt using org.springframework.security.authentication.dao.DaoAuthenticationProvider
[2013-10-03 13:45:11.275] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-10-03 13:45:11.275] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select client_id, client_secret, resource_ids, scope, authorized_grant_types, web_server_redirect_uri, authorities, access_token_validity, refresh_token_validity, additional_information from oauth_client_details where client_id = ?]
[2013-10-03 13:45:11.275] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Fetching JDBC Connection from DataSource
[2013-10-03 13:45:11.278] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Returning JDBC Connection to DataSource
[2013-10-03 13:45:11.420] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- BasicAuthenticationFilter: Authentication success: org.springframework.security.authentication.UsernamePasswordAuthenticationToken@1bd11d8f: Principal: org.springframework.security.core.userdetails.User@c63: Username: cf; Password: [PROTECTED]; Enabled: true; AccountNonExpired: true; credentialsNonExpired: true; AccountNonLocked: true; Granted Authorities: uaa.none; Credentials: [PROTECTED]; Authenticated: true; Details: remoteAddress=9.10.7.205; Granted Authorities: uaa.none
[2013-10-03 13:45:11.420] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- FilterChainProxy: /oauth/token at position 4 of 7 in additional filter chain; firing Filter: 'TokenEndpointAuthenticationFilter'
[2013-10-03 13:45:11.420] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- TokenEndpointAuthenticationFilter: Authentication credentials found for 'matt'
[2013-10-03 13:45:11.420] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- AuthzAuthenticationManager: Processing authentication request for matt
[2013-10-03 13:45:11.420] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-10-03 13:45:11.420] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select id,username,password,email,givenName,familyName,created,lastModified from users where lower(username) = ? and active=?]
[2013-10-03 13:45:11.420] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Fetching JDBC Connection from DataSource
[2013-10-03 13:45:11.421] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-10-03 13:45:11.421] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select g.displayName from groups g, group_membership m where g.id = m.group_id and m.member_id = ?]
[2013-10-03 13:45:11.421] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Fetching JDBC Connection from DataSource
[2013-10-03 13:45:11.422] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Returning JDBC Connection to DataSource
[2013-10-03 13:45:11.422] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Returning JDBC Connection to DataSource
[2013-10-03 13:45:11.565] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-10-03 13:45:11.565] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select event_type, principal_id, origin, event_data, created from sec_audit where principal_id=? and created > ? order by created desc]
[2013-10-03 13:45:11.565] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Fetching JDBC Connection from DataSource
[2013-10-03 13:45:11.566] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Returning JDBC Connection to DataSource
[2013-10-03 13:45:11.566] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- AuthzAuthenticationManager: Password successfully matched
[2013-10-03 13:45:11.566] uaa - 8519 [http-bio-80-exec-6] ....  INFO --- Audit: UserAuthenticationSuccess ('matt'): principal=186676e2-d9c4-4074-b395-55868a1f9168, origin=[remoteAddress=9.10.7.205]
[2013-10-03 13:45:11.567] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL update
[2013-10-03 13:45:11.567] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [delete from sec_audit where principal_id=?]
[2013-10-03 13:45:11.567] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Fetching JDBC Connection from DataSource
[2013-10-03 13:45:11.567] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: SQL update affected 0 rows
[2013-10-03 13:45:11.567] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Returning JDBC Connection to DataSource
[2013-10-03 13:45:11.567] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- TokenEndpointAuthenticationFilter: Authentication success: matt
[2013-10-03 13:45:11.567] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- FilterChainProxy: /oauth/token at position 5 of 7 in additional filter chain; firing Filter: 'SecurityContextHolderAwareRequestFilter'
[2013-10-03 13:45:11.567] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- FilterChainProxy: /oauth/token at position 6 of 7 in additional filter chain; firing Filter: 'ExceptionTranslationFilter'
[2013-10-03 13:45:11.567] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- FilterChainProxy: /oauth/token at position 7 of 7 in additional filter chain; firing Filter: 'FilterSecurityInterceptor'
[2013-10-03 13:45:11.567] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- FilterSecurityInterceptor: Secure object: FilterInvocation: URL: /oauth/token; Attributes: [IS_AUTHENTICATED_FULLY]
[2013-10-03 13:45:11.568] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- FilterSecurityInterceptor: Previously Authenticated: org.springframework.security.oauth2.provider.OAuth2Authentication@ae40ee: Principal: org.cloudfoundry.identity.uaa.authentication.UaaPrincipal@36a3a2ef; Credentials: [PROTECTED]; Authenticated: true; Details: null; Granted Authorities: scim.userids, scim.read, cloud_controller.admin, scim.write, scim.me, cloud_controller.write, password.write, openid, cloud_controller.read, approvals.me, uaa.user
[2013-10-03 13:45:11.568] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- AffirmativeBased: Voter: org.springframework.security.access.vote.RoleVoter@223e0d14, returned: 0
[2013-10-03 13:45:11.568] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- AffirmativeBased: Voter: org.springframework.security.access.vote.AuthenticatedVoter@17ccad9c, returned: 1
[2013-10-03 13:45:11.568] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- FilterSecurityInterceptor: Authorization successful
[2013-10-03 13:45:11.568] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- FilterSecurityInterceptor: RunAsManager did not change Authentication object
[2013-10-03 13:45:11.568] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- FilterChainProxy: /oauth/token reached end of additional filter chain; proceeding with original chain
[2013-10-03 13:45:11.568] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DispatcherServlet: DispatcherServlet with name 'spring' processing POST request for [/oauth/token]
[2013-10-03 13:45:11.568] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- RequestMappingHandlerMapping: Looking up handler method for path /oauth/token
[2013-10-03 13:45:11.568] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- RequestMappingHandlerMapping: Returning handler method [public org.springframework.http.ResponseEntity<org.springframework.security.oauth2.common.OAuth2AccessToken> org.springframework.security.oauth2.provider.endpoint.TokenEndpoint.getAccessToken(java.security.Principal,java.lang.String,java.util.Map<java.lang.String, java.lang.String>)]
[2013-10-03 13:45:11.569] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-10-03 13:45:11.569] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select client_id, client_secret, resource_ids, scope, authorized_grant_types, web_server_redirect_uri, authorities, access_token_validity, refresh_token_validity, additional_information from oauth_client_details where client_id = ?]
[2013-10-03 13:45:11.569] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Fetching JDBC Connection from DataSource
[2013-10-03 13:45:11.571] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Returning JDBC Connection to DataSource
[2013-10-03 13:45:11.571] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-10-03 13:45:11.571] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select client_id, client_secret, resource_ids, scope, authorized_grant_types, web_server_redirect_uri, authorities, access_token_validity, refresh_token_validity, additional_information from oauth_client_details where client_id = ?]
[2013-10-03 13:45:11.571] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Fetching JDBC Connection from DataSource
[2013-10-03 13:45:11.573] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Returning JDBC Connection to DataSource
[2013-10-03 13:45:11.573] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-10-03 13:45:11.573] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select client_id, client_secret, resource_ids, scope, authorized_grant_types, web_server_redirect_uri, authorities, access_token_validity, refresh_token_validity, additional_information from oauth_client_details where client_id = ?]
[2013-10-03 13:45:11.573] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Fetching JDBC Connection from DataSource
[2013-10-03 13:45:11.575] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Returning JDBC Connection to DataSource
[2013-10-03 13:45:11.575] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- ResourceOwnerPasswordTokenGranter: Getting access token for: cf
[2013-10-03 13:45:11.575] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-10-03 13:45:11.575] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select client_id, client_secret, resource_ids, scope, authorized_grant_types, web_server_redirect_uri, authorities, access_token_validity, refresh_token_validity, additional_information from oauth_client_details where client_id = ?]
[2013-10-03 13:45:11.575] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Fetching JDBC Connection from DataSource
[2013-10-03 13:45:11.577] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Returning JDBC Connection to DataSource
[2013-10-03 13:45:11.577] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-10-03 13:45:11.577] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select id,username,password,email,givenName,familyName,created,lastModified from users where lower(username) = ? and active=?]
[2013-10-03 13:45:11.577] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Fetching JDBC Connection from DataSource
[2013-10-03 13:45:11.578] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-10-03 13:45:11.578] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select g.displayName from groups g, group_membership m where g.id = m.group_id and m.member_id = ?]
[2013-10-03 13:45:11.578] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Fetching JDBC Connection from DataSource
[2013-10-03 13:45:11.578] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Returning JDBC Connection to DataSource
[2013-10-03 13:45:11.579] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Returning JDBC Connection to DataSource
[2013-10-03 13:45:11.581] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-10-03 13:45:11.581] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select id,username,password,email,givenName,familyName,created,lastModified from users where lower(username) = ? and active=?]
[2013-10-03 13:45:11.581] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Fetching JDBC Connection from DataSource
[2013-10-03 13:45:11.582] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-10-03 13:45:11.582] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select g.displayName from groups g, group_membership m where g.id = m.group_id and m.member_id = ?]
[2013-10-03 13:45:11.582] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Fetching JDBC Connection from DataSource
[2013-10-03 13:45:11.583] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Returning JDBC Connection to DataSource
[2013-10-03 13:45:11.583] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Returning JDBC Connection to DataSource
[2013-10-03 13:45:11.583] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL query
[2013-10-03 13:45:11.583] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select client_id, client_secret, resource_ids, scope, authorized_grant_types, web_server_redirect_uri, authorities, access_token_validity, refresh_token_validity, additional_information from oauth_client_details where client_id = ?]
[2013-10-03 13:45:11.583] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Fetching JDBC Connection from DataSource
[2013-10-03 13:45:11.585] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DataSourceUtils: Returning JDBC Connection to DataSource
[2013-10-03 13:45:11.588] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- HttpEntityMethodProcessor: Written [eyJhbGciOiJSUzI1NiJ9.eyJqdGkiOiI1NDBjMjEzMC00NjJiLTQ5YzgtODEwZC1jMDE5NGZhMTMwY2EiLCJzdWIiOiIxODY2NzZlMi1kOWM0LTQwNzQtYjM5NS01NTg2OGExZjkxNjgiLCJzY29wZSI6WyJjbG91ZF9jb250cm9sbGVyLmFkbWluIiwiY2xvdWRfY29udHJvbGxlci5yZWFkIiwiY2xvdWRfY29udHJvbGxlci53cml0ZSIsIm9wZW5pZCIsInBhc3N3b3JkLndyaXRlIiwic2NpbS5yZWFkIiwic2NpbS53cml0ZSJdLCJjbGllbnRfaWQiOiJjZiIsImNpZCI6ImNmIiwiZ3JhbnRfdHlwZSI6InBhc3N3b3JkIiwidXNlcl9pZCI6IjE4NjY3NmUyLWQ5YzQtNDA3NC1iMzk1LTU1ODY4YTFmOTE2OCIsInVzZXJfbmFtZSI6Im1hdHQiLCJlbWFpbCI6Im1hdHQiLCJpYXQiOjEzODA4MDc5MTEsImV4cCI6MTM4MDgxNTExMSwiaXNzIjoiaHR0cHM6Ly91YWEuaW50LmZ0MS5jcGdwYWFzLm5ldC9vYXV0aC90b2tlbiIsImF1ZCI6WyJzY2ltIiwib3BlbmlkIiwiY2xvdWRfY29udHJvbGxlciIsInBhc3N3b3JkIl19.LhmskrQpAoKpnBkiFKz1c9th5PId7lrui3DuC0BqWv_rfEZ8I2QL9lYhd3AfBdzMNP5s6oxal9TIRqMk8GqTgGD8iosXidMc76h2kqdSE4TIfRKZaM3yM_jHx6w755-hsc1OYj1uLpangb7wnGY_H0RBHssRR20e1kj9Wll_NXU] as "application/json;charset=UTF-8" using [org.springframework.http.converter.json.MappingJacksonHttpMessageConverter@155ec9f4]
[2013-10-03 13:45:11.588] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DispatcherServlet: Null ModelAndView returned to DispatcherServlet with name 'spring': assuming HandlerAdapter completed request handling
[2013-10-03 13:45:11.588] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- DispatcherServlet: Successfully completed request
[2013-10-03 13:45:11.589] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- ExceptionTranslationFilter: Chain processed normally
[2013-10-03 13:45:11.589] uaa - 8519 [http-bio-80-exec-6] .... DEBUG --- SecurityContextPersistenceFilter: SecurityContextHolder now cleared, as request processing completed

Sorry, yes this is long, saves asking for logs and details later right? ;)

So then i started wondering if it's because they are SCIM users defined in the cf.yml and if that affects things, so i tried uaac rubygem;

matt@matjohn2-mac cf-install (bxbft2) $ uaac token get matt
Password:  ****
CF::UAA::BadResponse: status 401
attempt to get token failed

Can't login here either. 401 is unauthorized :(

log extract; looks like this still uses the old 'vmc' client name rather than 'cf'

[2013-10-03 14:00:51.434] uaa - 8519 [http-bio-80-exec-10] .... DEBUG --- ExceptionHandlerExceptionResolver: Invoking @ExceptionHandler method: public org.springframework.web.servlet.ModelAndView org.springframework.security.oauth2.provider.endpoint.AuthorizationEndpoint.handleClientRegistrationException(java.lang.Exception,org.springframework.web.context.request.ServletWebRequest) throws java.lang.Exception
[2013-10-03 14:00:51.434] uaa - 8519 [http-bio-80-exec-10] ....  INFO --- AuthorizationEndpoint: Handling ClientRegistrationException error: No client with requested id: vmc
[2013-10-03 14:00:51.434] uaa - 8519 [http-bio-80-exec-10] .... DEBUG --- DispatcherServlet: Handler execution resulted in exception - forwarding to resolved error view: ModelAndView: reference to view with name 'forward:/oauth/error'; model is {error=error="invalid_client", error_description="Bad client credentials"}
org.springframework.security.oauth2.provider.NoSuchClientException: No client with requested id: vmc

So creating a new vmc client in my cf.yml;

      cf:
        #id: cf
        override: true
        authorized-grant-types: password,implicit,refresh_token
        authorities: uaa.none
        scope: cloud_controller.read,cloud_controller.write,openid,password.write,cloud_controller.admin,scim.read,scim.write
        access-token-validity: 7200
        refresh-token-validity: 1209600

      vmc:
        #id: cf
        override: true
        authorized-grant-types: password,implicit,refresh_token
        authorities: uaa.none
        scope: cloud_controller.read,cloud_controller.write,openid,password.write,cloud_controller.admin,scim.read,scim.write
        access-token-validity: 7200
        refresh-token-validity: 1209600

bosh deploy

Wohoo, uaac success;

matt@matjohn2-mac cf-install (bxbft2) $ uaac token get matt
Password:  ****

Successfully fetched token via implicit (with posted credentials) grant.
Target: http://uaa.int.ft1.cpgpaas.net
Context: matt, from client vmc

Still the same error in cf login though. So i carry on thinking i need a 'proper' user, created in uaac (maybe?);

matt@matjohn2-mac cf-install (bxbft2) $ uaac user add tastle --given_name troy --family_name a --emails b...@bob.com -p troy
user account successfully added
matt@matjohn2-mac cf-install (bxbft2) $ uaac users
  admin
    id: bdf8e0f8-86f2-451b-82e6-e6d1d3e49d66
    meta
      version: 1
      created: 2013-10-03T13:07:14.827Z
      lastmodified: 2013-10-03T14:04:10.768Z
    name
    emails:
    -
      value: admin
    groups:
    -
      value: 4cf85a2a-d17b-4601-8ade-abfa3d2ba4a0
      display: password.write
      type: DIRECT
    -
      value: b494262d-c6a4-4c53-9315-b34a07faaf58
      display: cloud_controller.write
      type: DIRECT
    -
      value: 88e84e97-071c-4ae9-ac9f-4ab9b7b2bb94
      display: scim.read
      type: DIRECT
    -
      value: 2f06e3fa-16a3-450d-b3fc-dfdd4b79cb29
      display: uaa.user
      type: DIRECT
    -
      value: f6bd4c5d-3c00-4a61-a7f8-63eddba9b40a
      display: openid
      type: DIRECT
    -
      value: 08b31071-30f9-4360-ab08-10f03c2004e8
      display: cloud_controller.admin
      type: DIRECT
    -
      value: 7bafa010-5aab-4645-85bd-beee8f494b81
      display: scim.write
      type: DIRECT
    -
      value: baef184b-7e92-46d6-b8cf-77747a38c0ce
      display: approvals.me
      type: DIRECT
    -
      value: 34544a0e-36ab-4687-b458-6c60f7c0aca9
      display: cloud_controller.read
      type: DIRECT
    -
      value: 5ae07df0-f810-4844-a52b-a40b3e4ae204
      display: scim.userids
      type: DIRECT
    -
      value: f1117e84-fcad-4f64-858e-6eba948c2436
      display: scim.me
      type: DIRECT
    approvals:
    active: true
    schemas: urn:scim:schemas:core:1.0
  services
    id: 56e2533f-6442-4437-ba37-460ee805fd4a
    meta
      version: 1
      created: 2013-10-03T13:07:15.123Z
      lastmodified: 2013-10-03T14:04:11.102Z
    name
    emails:
    -
      value: services
    groups:
    -
      value: 4cf85a2a-d17b-4601-8ade-abfa3d2ba4a0
      display: password.write
      type: DIRECT
    -
      value: b494262d-c6a4-4c53-9315-b34a07faaf58
      display: cloud_controller.write
      type: DIRECT
    -
      value: 88e84e97-071c-4ae9-ac9f-4ab9b7b2bb94
      display: scim.read
      type: DIRECT
    -
      value: 2f06e3fa-16a3-450d-b3fc-dfdd4b79cb29
      display: uaa.user
      type: DIRECT
    -
      value: f6bd4c5d-3c00-4a61-a7f8-63eddba9b40a
      display: openid
      type: DIRECT
    -
      value: 08b31071-30f9-4360-ab08-10f03c2004e8
      display: cloud_controller.admin
      type: DIRECT
    -
      value: 7bafa010-5aab-4645-85bd-beee8f494b81
      display: scim.write
      type: DIRECT
    -
      value: baef184b-7e92-46d6-b8cf-77747a38c0ce
      display: approvals.me
      type: DIRECT
    -
      value: 34544a0e-36ab-4687-b458-6c60f7c0aca9
      display: cloud_controller.read
      type: DIRECT
    -
      value: 5ae07df0-f810-4844-a52b-a40b3e4ae204
      display: scim.userids
      type: DIRECT
    -
      value: f1117e84-fcad-4f64-858e-6eba948c2436
      display: scim.me
      type: DIRECT
    approvals:
    active: true
    schemas: urn:scim:schemas:core:1.0
  matt
    id: 186676e2-d9c4-4074-b395-55868a1f9168
    meta
      version: 1
      created: 2013-10-03T13:07:15.318Z
      lastmodified: 2013-10-03T14:04:11.346Z
    name
    emails:
    -
      value: matt
    groups:
    -
      value: 4cf85a2a-d17b-4601-8ade-abfa3d2ba4a0
      display: password.write
      type: DIRECT
    -
      value: b494262d-c6a4-4c53-9315-b34a07faaf58
      display: cloud_controller.write
      type: DIRECT
    -
      value: 88e84e97-071c-4ae9-ac9f-4ab9b7b2bb94
      display: scim.read
      type: DIRECT
    -
      value: 2f06e3fa-16a3-450d-b3fc-dfdd4b79cb29
      display: uaa.user
      type: DIRECT
    -
      value: f6bd4c5d-3c00-4a61-a7f8-63eddba9b40a
      display: openid
      type: DIRECT
    -
      value: 08b31071-30f9-4360-ab08-10f03c2004e8
      display: cloud_controller.admin
      type: DIRECT
    -
      value: 7bafa010-5aab-4645-85bd-beee8f494b81
      display: scim.write
      type: DIRECT
    -
      value: baef184b-7e92-46d6-b8cf-77747a38c0ce
      display: approvals.me
      type: DIRECT
    -
      value: 34544a0e-36ab-4687-b458-6c60f7c0aca9
      display: cloud_controller.read
      type: DIRECT
    -
      value: 5ae07df0-f810-4844-a52b-a40b3e4ae204
      display: scim.userids
      type: DIRECT
    -
      value: f1117e84-fcad-4f64-858e-6eba948c2436
      display: scim.me
      type: DIRECT
    approvals:
    active: true
    schemas: urn:scim:schemas:core:1.0
  tastle
    id: c379b9f9-0b5c-4302-850a-9df544adc138
    meta
      version: 0
      created: 2013-10-03T14:06:01.733Z
      lastmodified: 2013-10-03T14:06:01.733Z
    name
      familyname: astle
      givenname: troy
    emails:
    -
      value: tas...@bob.com
    groups:
    -
      value: 4cf85a2a-d17b-4601-8ade-abfa3d2ba4a0
      display: password.write
      type: DIRECT
    -
      value: b494262d-c6a4-4c53-9315-b34a07faaf58
      display: cloud_controller.write
      type: DIRECT
    -
      value: 2f06e3fa-16a3-450d-b3fc-dfdd4b79cb29
      display: uaa.user
      type: DIRECT
    -
      value: f6bd4c5d-3c00-4a61-a7f8-63eddba9b40a
      display: openid
      type: DIRECT
    -
      value: baef184b-7e92-46d6-b8cf-77747a38c0ce
      display: approvals.me
      type: DIRECT
    -
      value: 34544a0e-36ab-4687-b458-6c60f7c0aca9
      display: cloud_controller.read
      type: DIRECT
    -
      value: 5ae07df0-f810-4844-a52b-a40b3e4ae204
      display: scim.userids
      type: DIRECT
    -
      value: f1117e84-fcad-4f64-858e-6eba948c2436
      display: scim.me
      type: DIRECT
    approvals:
    active: true
    schemas: urn:scim:schemas:core:1.0

No luck;

matt@matjohn2-mac cf-install (bxbft2) $ cf login
target: https://api.int.ft1.cpgpaas.net
Email> tastle
Password> ****
Authenticating... OK
Invalid authentication token. Try logging in again with 'cf login'. If problems continue, please contact your Cloud Operator.

At this point i'm sure i've missed something, somewhere. But i'm hoping someone could shine a light on where?

Thanks,

Matt

FYI:

matt@matjohn2-mac cf-install (bxbft2) $ uaac token decode

Note: no key given to validate token signature

  jti: 8074ffa4-ad02-44ef-a009-c2b874144bed
  sub: 186676e2-d9c4-4074-b395-55868a1f9168
  scope: scim.read cloud_controller.admin password.write scim.write cloud_controller.write openid cloud_controller.read
  client_id: vmc
  cid: vmc
  user_id: 186676e2-d9c4-4074-b395-55868a1f9168
  user_name: matt
  email: matt
  iat: 1380809077
  exp: 1380816277
  iss: https://uaa.int.ft1.cpgpaas.net/oauth/token
  aud: scim openid cloud_controller password

Dr Nic Williams

unread,

Oct 3, 2013, 2:59:23 PM10/3/13

to vcap...@cloudfoundry.org

Perhaps you also need the uaa.clients.matt section.

For example from http://docs.cloudfoundry.com/docs/running/deploying-cf/openstack/install_cf_openstack.html we specify for the admin user:


      admin:
        secret: <%= common_password %>
        authorized-grant-types: client_credentials
        authorities: clients.read,clients.write,clients.secret,password.write,scim.read,uaa.admin

To unsubscribe from this group and stop receiving emails from it, send an email to vcap-dev+u...@cloudfoundry.org.

Dr Nic Williams

Stark & Wayne LLC - consultancy for Cloud Foundry users

http://drnicwilliams.com

http://starkandwayne.com

cell +1 (415) 860-2185

twitter @drnic

James Bayer

unread,

Oct 3, 2013, 3:23:52 PM10/3/13

to vcap...@cloudfoundry.org

passing along some comments from dave syer…

The vmc/cf client id mixup is obvisouly a problem (and might require the user's uaac and cf gems to be up to date to be consistent). But I see a valid token coming from the UAA in the middle there so I think the "invalid token" message some from the CloudController. Is there a problem with the key configuration for token validation?

Thank you,

James Bayer

Message has been deleted

m...@matt-j.co.uk

unread,

Oct 3, 2013, 5:44:37 PM10/3/13

to vcap...@cloudfoundry.org

Many thanks,

Good to know.. I had a feeling it was something todo with the CC as the cf command at least touches api.xxxx for 'cf login' requests where as the login web UI doesn't so seemed logical.

I'll have a re-read of the cloud_controller properties in the meantime, but how is the CC meant to verify tokens from the UAA? (if thats indeed what i think you are getting at?)

I can see a properties.uaa.cc.client_secret which I already have set to a random value. and can't see anywhere else that a key would be set that relates to CC?

 cc:
    srv_api_uri: (( "https://api." domain ))
    bulk_api_password: (( merge ))
    staging_upload_user: (( merge ))
    staging_upload_password: (( merge ))
    db_encryption_key: (( merge ))
    tasks_disabled: false

 
  uaa:
    cc:
      client_secret: (( merge ))

Also, there doesn't seem to be a matching uaa.client section for CC, so i tried defining it, guessing this is useless?

      cc:
       token_secret: cctokensecret
       client_secret: ccclientsecret
       authorized-grant-types: password,implicit,authorization_code,client_credentials,refresh_token
       scope: cloud_controller.read,cloud_controller.write,openid,password.write,cloud_controller.admin,scim.read,scim.write

Is there anywhere else I should be defining CC-to-UAA token validation keys?

Regards,

Matt

m...@matt-j.co.uk

unread,

Oct 3, 2013, 5:51:00 PM10/3/13

to vcap...@cloudfoundry.org

Hi Nic,

I could (probably) be wrong, but i think the 'admin' client is to allow a shared secret based authentication option for clients instead of the normal login options, for example I already have the following section;

 admin:
       client_secret: adminclientsecret
       authorized-grant-types: client_credentials
       authorities: uaa.admin,clients.read,clients.write,cloud_controller.read,cloud_controller.write,openid,password.write,cloud_controller.admin,scim.read,scim.write
       scope: uaa.admin,clients.read,clients.write,cloud_controller.read,cloud_controller.write,openid,password.write,cloud_controller.admin,scim.read,scim.write

And I can then authenticate to uaac without a regular user as follows;

uaac token client get admin -s adminclientsecret

which will give you an admin token for uaac to manage all of the things.

cf login with admin also gives the same error.

Matt

Matt Johnson

unread,

Oct 3, 2013, 6:37:00 PM10/3/13

to vcap...@cloudfoundry.org

FIXED!

Seems i'd been moving closer and closer to a working solution throughout the debugging in my initial posting.

However, I still had a couple of bits left over from avenues of investigation that I was trying and one of them was clearly tripping things up;

1. properties.uaa.clients.cc (as posted above in a reply); cc isn't meant to be a client type

-or-

2. i had defined client_token as well as client_secret under properties.uaa.cc; this wasn't needed either (not actually sure which corner of the internet this one came from!).

Thanks for the help guys!

Matt

James Bayer

unread,

Oct 5, 2013, 7:51:22 PM10/5/13

to vcap...@cloudfoundry.org

BTW, Joel D'sa from the original UAA team replied with a helpful snippet below after the issue was fixed. Hopefully Ryan Morgan and team can look into how to approach this going forward.

-----

log extract; looks like this still uses the old 'vmc' client name rather than 'cf'

[2013-10-03 14:00:51.434] uaa - 8519 [http-bio-80-exec-10] .... DEBUG ---ExceptionHandlerExceptionResolver: Invoking @ExceptionHandler method: publicorg.springframework.web.servlet.ModelAndView org.springframework.security.oauth2.provider.endpoint.AuthorizationEndpoint.handleClientRegistrationException(java.lang.Exception,org.springframework.web.context.request.ServletWebRequest) throws java.lang.Exception
[2013-10-03 14:00:51.434] uaa - 8519 [http-bio-80-exec-10] .... INFO ---AuthorizationEndpoint: Handling ClientRegistrationException error: No client withrequested id: vmc
[2013-10-03 14:00:51.434] uaa - 8519 [http-bio-80-exec-10] .... DEBUG ---DispatcherServlet: Handler execution resulted in exception - forwarding to resolved error view: ModelAndView: reference to view with name 'forward:/oauth/error'; modelis {error=error="invalid_client", error_description="Bad client credentials"}

org.springframework.security.oauth2.provider.NoSuchClientException: No client withrequested id: vmc

This is a valid issue. When we switched to cf from vmc, we did not change the uaac implicit flow to use the cf client rather than vmc. It was hardcoded for testing and CI.

Thank you,

James Bayer

Reply all

Reply to author

Forward

0 new messages