[2019-03-22 10:13:04.205] uaa - 26265 [https-jsse-nio-8443-exec-10] .... DEBUG --- NestedLdapAuthoritiesPopulator: Search aborted, max depth reached, for roles for user 'CN=group1,OU=Groups,OU=DCS,dc=vclass,dc=local', DN = 'CN=group2,OU=Groups,OU=DCS,dc=vclass,dc=local', with filter member={0} in search base 'dc=vclass,dc=local'
[2019-03-22 10:13:04.205] uaa - 26265 [https-jsse-nio-8443-exec-10] .... DEBUG --- NestedLdapAuthoritiesPopulator: Roles from LDAP search:1.[Key:spring.security.ldap.dn Values:CN=group1,OU=Groups,OU=DCS,dc=vclass,dc=local; ]
[2019-03-22 10:13:03.119] uaa - 26265 [http-nio-35684-exec-4] .... DEBUG --- FilterChainProxy: /healthz has an empty filter list
.
.
[2019-03-22 10:11:07.168] uaa - 26265 [pool-2-thread-1] .... DEBUG --- JdbcTemplate: Executing SQL query [select count(*) from users]
[2019-03-22 10:11:03.061] uaa - 26265 [http-nio-35684-exec-2] .... DEBUG --- FilterChainProxy: /healthz has an empty filter list
[2019-03-22 10:11:02.169] uaa - 26265 [pool-2-thread-1] .... DEBUG --- JdbcTemplate: Executing SQL query [select count(*) from oauth_client_details]
[2019-03-22 10:11:02.168] uaa - 26265 [pool-2-thread-1] .... DEBUG --- JdbcTemplate: Executing SQL query [select count(*) from users]
[2019-03-22 10:10:57.169] uaa - 26265 [pool-2-thread-1] .... DEBUG --- JdbcTemplate: Executing SQL query [select count(*) from oauth_client_details]
[2019-03-22 10:10:57.168] uaa - 26265 [pool-2-thread-1] .... DEBUG --- JdbcTemplate: Executing SQL query [select count(*) from users]
[2019-03-22 10:10:53.152] uaa - 26265 [https-jsse-nio-8443-exec-10] .... DEBUG --- SpringSecurityLdapTemplate: No attribute value found for 'spring.security.ldap.dn'
[2019-03-22 10:10:53.152] uaa - 26265 [https-jsse-nio-8443-exec-10] .... DEBUG --- SpringSecurityLdapTemplate: No attribute value found for 'spring.security.ldap.dn'
[2019-03-22 10:10:53.152] uaa - 26265 [https-jsse-nio-8443-exec-10] .... DEBUG --- SpringSecurityLdapTemplate: No attribute value found for 'spring.security.ldap.dn'
[2019-03-22 10:10:53.152] uaa - 26265 [https-jsse-nio-8443-exec-10] .... DEBUG --- SpringSecurityLdapTemplate: No attribute value found for 'spring.security.ldap.dn'
[2019-03-22 10:10:53.148] uaa - 26265 [https-jsse-nio-8443-exec-10] .... DEBUG --- SpringSecurityLdapTemplate: Using filter: member=cn=Test User,OU=Admins,OU=Users,dc=vclass,dc=local
[2019-03-22 10:10:53.148] uaa - 26265 [https-jsse-nio-8443-exec-10] .... DEBUG --- NestedLdapAuthoritiesPopulator: Searching for roles for user 'test_user', DN = 'cn=Test User,OU=Admins,OU=Users,dc=vclass,dc=local', with filter member={0} in search base 'dc=vclass,dc=local'
[2019-03-22 10:10:53.148] uaa - 26265 [https-jsse-nio-8443-exec-10] .... DEBUG --- DefaultLdapAuthoritiesPopulator: Getting authorities for user cn=Test User,OU=Admins,OU=Users,dc=vclass,dc=local
[2019-03-22 10:10:53.148] uaa - 26265 [https-jsse-nio-8443-exec-10] .... DEBUG --- BindAuthenticator: Retrieving attributes...
[2019-03-22 10:10:53.142] uaa - 26265 [https-jsse-nio-8443-exec-10] .... DEBUG --- BindAuthenticator: Attempting to bind as cn=Test User,OU=Admins,OU=Users,dc=vclass,dc=local
[2019-03-22 10:08:42.994] uaa - 26265 [http-nio-35684-exec-8] .... DEBUG --- FilterChainProxy: /healthz has an empty filter list
[2019-03-22 10:08:42.169] uaa - 26265 [pool-2-thread-1] .... DEBUG --- JdbcTemplate: Executing SQL query [select count(*) from oauth_client_details]
[2019-03-22 10:08:42.168] uaa - 26265 [pool-2-thread-1] .... DEBUG --- JdbcTemplate: Executing SQL query [select count(*) from users]
[2019-03-22 10:08:41.544] uaa - 26265 [https-jsse-nio-8443-exec-10] .... DEBUG --- SpringSecurityLdapTemplate: Found DN: CN=Test User,OU=Admins,OU=Users,dc=vclass,dc=local
[2019-03-22 10:08:41.544] uaa - 26265 [https-jsse-nio-8443-exec-10] .... DEBUG --- SpringSecurityLdapTemplate: Searching for entry under DN '', base = 'dc=vclass,dc=local', filter = 'sAMAccountName={0}'
[2019-03-22 10:08:41.540] uaa - 26265 [https-jsse-nio-8443-exec-10] .... DEBUG --- ProviderManager: Authentication attempt using org.springframework.security.ldap.authentication.LdapAuthenticationProvider
[2019-03-22 10:08:41.540] uaa - 26265 [https-jsse-nio-8443-exec-10] .... DEBUG --- ChainedAuthenticationManager: Attempting chained authentication of org.springframework.security.authentication.UsernamePasswordAuthenticationToken@508164f4: Principal: test_user; Credentials: [PROTECTED]; Authenticated: false; Details: remoteAddress=LDAP_IP, clientId=pks_cli; Not granted any authorities with manager:org.springframework.security.authentication.ProviderManager@7871355c required:null
[2019-03-22 10:08:41.540] uaa - 26265 [https-jsse-nio-8443-exec-10] .... DEBUG --- ChainedAuthenticationManager: Attempting chained authentication of org.springframework.security.authentication.UsernamePasswordAuthenticationToken@508164f4: Principal: test_user; Credentials: [PROTECTED]; Authenticated: false; Details: remoteAddress=LDAP_IP, clientId=pks_cli; Not granted any authorities with manager:org.cloudfoundry.identity.uaa.authentication.manager.DynamicLdapAuthenticationManager@51313b0a required:ifPreviousFalse
[2019-03-22 10:08:41.540] uaa - 26265 [https-jsse-nio-8443-exec-10] .... DEBUG --- ChainedAuthenticationManager: Chained Authentication status of org.springframework.security.authentication.UsernamePasswordAuthenticationToken@508164f4: Principal: test_user; Credentials: [PROTECTED]; Authenticated: false; Details: remoteAddress=LDAP_IP, clientId=pks_cli; Not granted any authorities with manager:org.cloudfoundry.identity.uaa.authentication.manager.ChainedAuthenticationManager$AuthenticationManagerConfiguration@324c350; Authenticated:false
[2019-03-22 10:08:41.540] uaa - 26265 [https-jsse-nio-8443-exec-10] .... DEBUG --- ChainedAuthenticationManager: Chained authentication exception:Bad credentials at:org.cloudfoundry.identity.uaa.authentication.manager.AuthzAuthenticationManager.authenticate(AuthzAuthenticationManager.java:136)
[2019-03-22 10:08:41.540] uaa - 26265 [https-jsse-nio-8443-exec-10] .... INFO --- Audit: PrincipalAuthenticationFailure ('null'): principal=test_user, origin=[LDAP_IP], identityZoneId=[uaa]
[2019-03-22 10:08:41.540] uaa - 26265 [https-jsse-nio-8443-exec-10] .... INFO --- Audit: UserNotFound (''): principal=HQt7aKON4WYK7GqSK5YSvzWdLyg=, origin=[remoteAddress=LDAP_IP, clientId=pks_cli], identityZoneId=[uaa]
[2019-03-22 10:08:41.540] uaa - 26265 [https-jsse-nio-8443-exec-10] .... DEBUG --- AuthzAuthenticationManager: No user named 'test_user' was found for origin:uaa
[2019-03-22 10:08:41.540] uaa - 26265 [https-jsse-nio-8443-exec-10] .... DEBUG --- JdbcTemplate: Executing prepared SQL statement [select id,username,password,email,givenName,familyName,created,lastModified,authorities,origin,external_id,verified,identity_zone_id,salt,passwd_lastmodified,phoneNumber,legacy_verification_behavior,passwd_change_required,last_logon_success_time,previous_logon_success_time from users where username = ? and active=? and origin=? and identity_zone_id=?]
This issue occurs when the LDAP search takes long time and aborted at last.Typically we see long delays when uaa is doing an ldap search.By default uaa will follow referrals and sometimes there is a referred DC that is taking too long to respond.
To resolve this issue, investigate why the referrals are taking too long to return the search results.
To work around this issue, disable the referrals by selecting the Ignore referrals and return partial result option for LDAP Referrals under UAA section in PKS Tile, and apply changes from Ops Manager.