Restructure LDAP Logs

Issue gh-6311
This commit is contained in:
Josh Cummings 2021-11-05 11:27:38 -06:00
parent 50196537e1
commit 3a3b2858d8
15 changed files with 92 additions and 81 deletions

View File

@ -28,6 +28,7 @@ import java.util.StringTokenizer;
import org.apache.commons.logging.Log; import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory; import org.apache.commons.logging.LogFactory;
import org.springframework.core.log.LogMessage;
import org.springframework.ldap.core.support.DirContextAuthenticationStrategy; import org.springframework.ldap.core.support.DirContextAuthenticationStrategy;
import org.springframework.ldap.core.support.LdapContextSource; import org.springframework.ldap.core.support.LdapContextSource;
import org.springframework.ldap.core.support.SimpleDirContextAuthenticationStrategy; import org.springframework.ldap.core.support.SimpleDirContextAuthenticationStrategy;
@ -72,7 +73,7 @@ public class DefaultSpringSecurityContextSource extends LdapContextSource {
String url = tokenizer.nextToken(); String url = tokenizer.nextToken();
String urlRootDn = LdapUtils.parseRootDnFromUrl(url); String urlRootDn = LdapUtils.parseRootDnFromUrl(url);
urls.add(url.substring(0, url.lastIndexOf(urlRootDn))); urls.add(url.substring(0, url.lastIndexOf(urlRootDn)));
this.logger.info(" URL '" + url + "', root DN is '" + urlRootDn + "'"); this.logger.info(LogMessage.format("Configure with URL %s and root DN %s", url, urlRootDn));
Assert.isTrue(rootDn == null || rootDn.equals(urlRootDn), Assert.isTrue(rootDn == null || rootDn.equals(urlRootDn),
"Root DNs must be the same when using multiple URLs"); "Root DNs must be the same when using multiple URLs");
rootDn = (rootDn != null) ? rootDn : urlRootDn; rootDn = (rootDn != null) ? rootDn : urlRootDn;
@ -89,7 +90,7 @@ public class DefaultSpringSecurityContextSource extends LdapContextSource {
// Remove the pooling flag unless authenticating as the 'manager' user. // Remove the pooling flag unless authenticating as the 'manager' user.
if (!DefaultSpringSecurityContextSource.this.userDn.equals(dn) if (!DefaultSpringSecurityContextSource.this.userDn.equals(dn)
&& env.containsKey(SUN_LDAP_POOLING_FLAG)) { && env.containsKey(SUN_LDAP_POOLING_FLAG)) {
DefaultSpringSecurityContextSource.this.logger.debug("Removing pooling flag for user " + dn); DefaultSpringSecurityContextSource.this.logger.trace("Removing pooling flag for user " + dn);
env.remove(SUN_LDAP_POOLING_FLAG); env.remove(SUN_LDAP_POOLING_FLAG);
} }
} }

View File

@ -53,7 +53,7 @@ public final class LdapUtils {
} }
} }
catch (NamingException ex) { catch (NamingException ex) {
logger.error("Failed to close context.", ex); logger.debug("Failed to close context.", ex);
} }
} }
@ -64,7 +64,7 @@ public final class LdapUtils {
} }
} }
catch (NamingException ex) { catch (NamingException ex) {
logger.error("Failed to close enumeration.", ex); logger.debug("Failed to close enumeration.", ex);
} }
} }

View File

@ -166,7 +166,7 @@ public class SpringSecurityLdapTemplate extends LdapTemplate {
encodedParams[i] = LdapEncoder.filterEncode(params[i].toString()); encodedParams[i] = LdapEncoder.filterEncode(params[i].toString());
} }
String formattedFilter = MessageFormat.format(filter, encodedParams); String formattedFilter = MessageFormat.format(filter, encodedParams);
logger.debug(LogMessage.format("Using filter: %s", formattedFilter)); logger.trace(LogMessage.format("Using filter: %s", formattedFilter));
HashSet<Map<String, List<String>>> result = new HashSet<>(); HashSet<Map<String, List<String>>> result = new HashSet<>();
ContextMapper roleMapper = (ctx) -> { ContextMapper roleMapper = (ctx) -> {
DirContextAdapter adapter = (DirContextAdapter) ctx; DirContextAdapter adapter = (DirContextAdapter) ctx;
@ -223,7 +223,7 @@ public class SpringSecurityLdapTemplate extends LdapTemplate {
String attributeName) { String attributeName) {
Object[] values = adapter.getObjectAttributes(attributeName); Object[] values = adapter.getObjectAttributes(attributeName);
if (values == null || values.length == 0) { if (values == null || values.length == 0) {
logger.debug(LogMessage.format("No attribute value found for '%s'", attributeName)); logger.debug(LogMessage.format("Did not find attribute value for %s", attributeName));
return; return;
} }
List<String> stringValues = new ArrayList<>(); List<String> stringValues = new ArrayList<>();
@ -233,9 +233,9 @@ public class SpringSecurityLdapTemplate extends LdapTemplate {
stringValues.add((String) value); stringValues.add((String) value);
} }
else { else {
logger.debug(LogMessage.format("Attribute:%s contains a non string value of type[%s]",
attributeName, value.getClass()));
stringValues.add(value.toString()); stringValues.add(value.toString());
logger.debug(LogMessage.format("Coerced attribute value for %s of type %s to a String",
attributeName, value.getClass()));
} }
} }
} }
@ -270,7 +270,7 @@ public class SpringSecurityLdapTemplate extends LdapTemplate {
final DistinguishedName searchBaseDn = new DistinguishedName(base); final DistinguishedName searchBaseDn = new DistinguishedName(base);
final NamingEnumeration<SearchResult> resultsEnum = ctx.search(searchBaseDn, filter, params, final NamingEnumeration<SearchResult> resultsEnum = ctx.search(searchBaseDn, filter, params,
buildControls(searchControls)); buildControls(searchControls));
logger.debug(LogMessage.format("Searching for entry under DN '%s', base = '%s', filter = '%s'", ctxBaseDn, logger.trace(LogMessage.format("Searching for entry under DN '%s', base = '%s', filter = '%s'", ctxBaseDn,
searchBaseDn, filter)); searchBaseDn, filter));
Set<DirContextOperations> results = new HashSet<>(); Set<DirContextOperations> results = new HashSet<>();
try { try {
@ -284,7 +284,7 @@ public class SpringSecurityLdapTemplate extends LdapTemplate {
} }
catch (PartialResultException ex) { catch (PartialResultException ex) {
LdapUtils.closeEnumeration(resultsEnum); LdapUtils.closeEnumeration(resultsEnum);
logger.info("Ignoring PartialResultException"); logger.trace("Ignoring PartialResultException");
} }
if (results.size() != 1) { if (results.size() != 1) {
throw new IncorrectResultSizeDataAccessException(1, results.size()); throw new IncorrectResultSizeDataAccessException(1, results.size());

View File

@ -24,7 +24,6 @@ import org.apache.commons.logging.LogFactory;
import org.springframework.context.MessageSource; import org.springframework.context.MessageSource;
import org.springframework.context.MessageSourceAware; import org.springframework.context.MessageSourceAware;
import org.springframework.context.support.MessageSourceAccessor; import org.springframework.context.support.MessageSourceAccessor;
import org.springframework.core.log.LogMessage;
import org.springframework.ldap.core.DirContextOperations; import org.springframework.ldap.core.DirContextOperations;
import org.springframework.security.authentication.AuthenticationProvider; import org.springframework.security.authentication.AuthenticationProvider;
import org.springframework.security.authentication.BadCredentialsException; import org.springframework.security.authentication.BadCredentialsException;
@ -68,7 +67,6 @@ public abstract class AbstractLdapAuthenticationProvider implements Authenticati
UsernamePasswordAuthenticationToken userToken = (UsernamePasswordAuthenticationToken) authentication; UsernamePasswordAuthenticationToken userToken = (UsernamePasswordAuthenticationToken) authentication;
String username = userToken.getName(); String username = userToken.getName();
String password = (String) authentication.getCredentials(); String password = (String) authentication.getCredentials();
this.logger.debug(LogMessage.format("Processing authentication request for user: %s", username));
if (!StringUtils.hasLength(username)) { if (!StringUtils.hasLength(username)) {
throw new BadCredentialsException( throw new BadCredentialsException(
this.messages.getMessage("LdapAuthenticationProvider.emptyUsername", "Empty Username")); this.messages.getMessage("LdapAuthenticationProvider.emptyUsername", "Empty Username"));
@ -104,6 +102,7 @@ public abstract class AbstractLdapAuthenticationProvider implements Authenticati
UsernamePasswordAuthenticationToken result = new UsernamePasswordAuthenticationToken(user, password, UsernamePasswordAuthenticationToken result = new UsernamePasswordAuthenticationToken(user, password,
this.authoritiesMapper.mapAuthorities(user.getAuthorities())); this.authoritiesMapper.mapAuthorities(user.getAuthorities()));
result.setDetails(authentication.getDetails()); result.setDetails(authentication.getDetails());
this.logger.debug("Authenticated user");
return result; return result;
} }

View File

@ -65,7 +65,7 @@ public class BindAuthenticator extends AbstractLdapAuthenticator {
String username = authentication.getName(); String username = authentication.getName();
String password = (String) authentication.getCredentials(); String password = (String) authentication.getCredentials();
if (!StringUtils.hasLength(password)) { if (!StringUtils.hasLength(password)) {
logger.debug(LogMessage.format("Rejecting empty password for user %s", username)); logger.debug(LogMessage.format("Failed to authenticate since no credentials provided"));
throw new BadCredentialsException( throw new BadCredentialsException(
this.messages.getMessage("BindAuthenticator.emptyPassword", "Empty Password")); this.messages.getMessage("BindAuthenticator.emptyPassword", "Empty Password"));
} }
@ -76,11 +76,18 @@ public class BindAuthenticator extends AbstractLdapAuthenticator {
break; break;
} }
} }
if (user == null) {
logger.debug(LogMessage.of(() -> "Failed to bind with any user DNs " + getUserDns(username)));
}
// Otherwise use the configured search object to find the user and authenticate // Otherwise use the configured search object to find the user and authenticate
// with the returned DN. // with the returned DN.
if (user == null && getUserSearch() != null) { if (user == null && getUserSearch() != null) {
logger.trace("Searching for user using " + getUserSearch());
DirContextOperations userFromSearch = getUserSearch().searchForUser(username); DirContextOperations userFromSearch = getUserSearch().searchForUser(username);
user = bindWithDn(userFromSearch.getDn().toString(), username, password, userFromSearch.getAttributes()); user = bindWithDn(userFromSearch.getDn().toString(), username, password, userFromSearch.getAttributes());
if (user == null) {
logger.debug("Failed to find user using " + getUserSearch());
}
} }
if (user == null) { if (user == null) {
throw new BadCredentialsException( throw new BadCredentialsException(
@ -98,13 +105,12 @@ public class BindAuthenticator extends AbstractLdapAuthenticator {
DistinguishedName userDn = new DistinguishedName(userDnStr); DistinguishedName userDn = new DistinguishedName(userDnStr);
DistinguishedName fullDn = new DistinguishedName(userDn); DistinguishedName fullDn = new DistinguishedName(userDn);
fullDn.prepend(ctxSource.getBaseLdapPath()); fullDn.prepend(ctxSource.getBaseLdapPath());
logger.debug(LogMessage.format("Attempting to bind as %s", fullDn)); logger.trace(LogMessage.format("Attempting to bind as %s", fullDn));
DirContext ctx = null; DirContext ctx = null;
try { try {
ctx = getContextSource().getContext(fullDn.toString(), password); ctx = getContextSource().getContext(fullDn.toString(), password);
// Check for password policy control // Check for password policy control
PasswordPolicyControl ppolicy = PasswordPolicyControlExtractor.extractControl(ctx); PasswordPolicyControl ppolicy = PasswordPolicyControlExtractor.extractControl(ctx);
logger.debug("Retrieving attributes...");
if (attrs == null || attrs.size() == 0) { if (attrs == null || attrs.size() == 0) {
attrs = ctx.getAttributes(userDn, getUserAttributes()); attrs = ctx.getAttributes(userDn, getUserAttributes());
} }
@ -112,6 +118,7 @@ public class BindAuthenticator extends AbstractLdapAuthenticator {
if (ppolicy != null) { if (ppolicy != null) {
result.setAttributeValue(ppolicy.getID(), ppolicy); result.setAttributeValue(ppolicy.getID(), ppolicy);
} }
logger.debug(LogMessage.format("Bound %s", fullDn));
return result; return result;
} }
catch (NamingException ex) { catch (NamingException ex) {
@ -141,7 +148,7 @@ public class BindAuthenticator extends AbstractLdapAuthenticator {
* logger. * logger.
*/ */
protected void handleBindException(String userDn, String username, Throwable cause) { protected void handleBindException(String userDn, String username, Throwable cause) {
logger.debug(LogMessage.format("Failed to bind as %s: %s", userDn, cause)); logger.trace(LogMessage.format("Failed to bind as %s", userDn), cause);
} }
} }

View File

@ -76,25 +76,37 @@ public final class PasswordComparisonAuthenticator extends AbstractLdapAuthentic
user = ldapTemplate.retrieveEntry(userDn, getUserAttributes()); user = ldapTemplate.retrieveEntry(userDn, getUserAttributes());
} }
catch (NameNotFoundException ignore) { catch (NameNotFoundException ignore) {
logger.trace(LogMessage.format("Failed to retrieve user with %s", userDn), ignore);
} }
if (user != null) { if (user != null) {
break; break;
} }
} }
if (user == null) {
logger.debug(LogMessage.of(() -> "Failed to retrieve user with any user DNs " + getUserDns(username)));
}
if (user == null && getUserSearch() != null) { if (user == null && getUserSearch() != null) {
logger.trace("Searching for user using " + getUserSearch());
user = getUserSearch().searchForUser(username); user = getUserSearch().searchForUser(username);
if (user == null) {
logger.debug("Failed to find user using " + getUserSearch());
}
} }
if (user == null) { if (user == null) {
throw new UsernameNotFoundException("User not found: " + username); throw new UsernameNotFoundException("User not found: " + username);
} }
if (logger.isDebugEnabled()) { if (logger.isTraceEnabled()) {
logger.debug(LogMessage.format("Performing LDAP compare of password attribute '%s' for user '%s'", logger.trace(LogMessage.format("Comparing password attribute '%s' for user '%s'",
this.passwordAttributeName, user.getDn())); this.passwordAttributeName, user.getDn()));
} }
if (this.usePasswordAttrCompare && isPasswordAttrCompare(user, password)) { if (this.usePasswordAttrCompare && isPasswordAttrCompare(user, password)) {
logger.debug(LogMessage.format("Locally matched password attribute '%s' for user '%s'",
this.passwordAttributeName, user.getDn()));
return user; return user;
} }
if (isLdapPasswordCompare(user, ldapTemplate, password)) { if (isLdapPasswordCompare(user, ldapTemplate, password)) {
logger.debug(LogMessage.format("LDAP-matched password attribute '%s' for user '%s'",
this.passwordAttributeName, user.getDn()));
return user; return user;
} }
throw new BadCredentialsException( throw new BadCredentialsException(

View File

@ -48,7 +48,7 @@ public class SpringSecurityAuthenticationSource implements AuthenticationSource
public String getPrincipal() { public String getPrincipal() {
Authentication authentication = SecurityContextHolder.getContext().getAuthentication(); Authentication authentication = SecurityContextHolder.getContext().getAuthentication();
if (authentication == null) { if (authentication == null) {
log.warn("No Authentication object set in SecurityContext - returning empty String as Principal"); log.debug("Returning empty String as Principal since authentication is null");
return ""; return "";
} }
Object principal = authentication.getPrincipal(); Object principal = authentication.getPrincipal();
@ -57,7 +57,7 @@ public class SpringSecurityAuthenticationSource implements AuthenticationSource
return details.getDn(); return details.getDn();
} }
if (authentication instanceof AnonymousAuthenticationToken) { if (authentication instanceof AnonymousAuthenticationToken) {
log.debug("Anonymous Authentication, returning empty String as Principal"); log.debug("Returning empty String as Principal since authentication is anonymous");
return ""; return "";
} }
throw new IllegalArgumentException( throw new IllegalArgumentException(
@ -71,7 +71,7 @@ public class SpringSecurityAuthenticationSource implements AuthenticationSource
public String getCredentials() { public String getCredentials() {
Authentication authentication = SecurityContextHolder.getContext().getAuthentication(); Authentication authentication = SecurityContextHolder.getContext().getAuthentication();
if (authentication == null) { if (authentication == null) {
log.warn("No Authentication object set in SecurityContext - returning empty String as Credentials"); log.debug("Returning empty String as Credentials since authentication is null");
return ""; return "";
} }
return (String) authentication.getCredentials(); return (String) authentication.getCredentials();

View File

@ -50,8 +50,7 @@ public class PasswordPolicyAwareContextSource extends DefaultSpringSecurityConte
if (principal.equals(this.userDn)) { if (principal.equals(this.userDn)) {
return super.getContext(principal, credentials); return super.getContext(principal, credentials);
} }
this.logger this.logger.trace(LogMessage.format("Binding as %s, prior to reconnect as user %s", this.userDn, principal));
.debug(LogMessage.format("Binding as '%s', prior to reconnect as user '%s'", this.userDn, principal));
// First bind as manager user before rebinding as the specific principal. // First bind as manager user before rebinding as the specific principal.
LdapContext ctx = (LdapContext) super.getContext(this.userDn, this.password); LdapContext ctx = (LdapContext) super.getContext(this.userDn, this.password);
Control[] rctls = { new PasswordPolicyControl(false) }; Control[] rctls = { new PasswordPolicyControl(false) };
@ -63,8 +62,7 @@ public class PasswordPolicyAwareContextSource extends DefaultSpringSecurityConte
catch (javax.naming.NamingException ex) { catch (javax.naming.NamingException ex) {
PasswordPolicyResponseControl ctrl = PasswordPolicyControlExtractor.extractControl(ctx); PasswordPolicyResponseControl ctrl = PasswordPolicyControlExtractor.extractControl(ctx);
if (this.logger.isDebugEnabled()) { if (this.logger.isDebugEnabled()) {
this.logger.debug("Failed to obtain context", ex); this.logger.debug(LogMessage.format("Failed to bind with %s", ctrl), ex);
this.logger.debug("Password policy response: " + ctrl);
} }
LdapUtils.closeContext(ctx); LdapUtils.closeContext(ctx);
if (ctrl != null && ctrl.isLocked()) { if (ctrl != null && ctrl.isLocked()) {
@ -72,8 +70,7 @@ public class PasswordPolicyAwareContextSource extends DefaultSpringSecurityConte
} }
throw LdapUtils.convertLdapException(ex); throw LdapUtils.convertLdapException(ex);
} }
this.logger.debug( this.logger.debug(LogMessage.of(() -> "Bound with " + PasswordPolicyControlExtractor.extractControl(ctx)));
LogMessage.of(() -> "PPolicy control returned: " + PasswordPolicyControlExtractor.extractControl(ctx)));
return ctx; return ctx;
} }

View File

@ -43,7 +43,7 @@ public final class PasswordPolicyControlExtractor {
ctrls = ctx.getResponseControls(); ctrls = ctx.getResponseControls();
} }
catch (javax.naming.NamingException ex) { catch (javax.naming.NamingException ex) {
logger.error("Failed to obtain response controls", ex); logger.trace("Failed to obtain response controls", ex);
} }
for (int i = 0; ctrls != null && i < ctrls.length; i++) { for (int i = 0; ctrls != null && i < ctrls.length; i++) {
if (ctrls[i] instanceof PasswordPolicyResponseControl) { if (ctrls[i] instanceof PasswordPolicyResponseControl) {

View File

@ -31,6 +31,7 @@ import netscape.ldap.ber.stream.BERTagDecoder;
import org.apache.commons.logging.Log; import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory; import org.apache.commons.logging.LogFactory;
import org.springframework.core.log.LogMessage;
import org.springframework.dao.DataRetrievalFailureException; import org.springframework.dao.DataRetrievalFailureException;
/** /**
@ -158,19 +159,21 @@ public class PasswordPolicyResponseControl extends PasswordPolicyControl {
*/ */
@Override @Override
public String toString() { public String toString() {
StringBuilder sb = new StringBuilder("PasswordPolicyResponseControl"); StringBuilder sb = new StringBuilder();
sb.append(getClass().getSimpleName()).append(" [");
if (hasError()) { if (hasError()) {
sb.append(", error: ").append(this.errorStatus.getDefaultMessage()); sb.append("error=").append(this.errorStatus.getDefaultMessage()).append("; ");
} }
if (this.graceLoginsRemaining != Integer.MAX_VALUE) { if (this.graceLoginsRemaining != Integer.MAX_VALUE) {
sb.append(", warning: ").append(this.graceLoginsRemaining).append(" grace logins remain"); sb.append("warning=").append(this.graceLoginsRemaining).append(" grace logins remain; ");
} }
if (this.timeBeforeExpiration != Integer.MAX_VALUE) { if (this.timeBeforeExpiration != Integer.MAX_VALUE) {
sb.append(", warning: time before expiration is ").append(this.timeBeforeExpiration); sb.append("warning=time before expiration is ").append(this.timeBeforeExpiration).append("; ");
} }
if (!hasError() && !hasWarning()) { if (!hasError() && !hasWarning()) {
sb.append(" (no error, no warning)"); sb.append("(no error, no warning)");
} }
sb.append("]");
return sb.toString(); return sb.toString();
} }
@ -192,7 +195,8 @@ public class PasswordPolicyResponseControl extends PasswordPolicyControl {
new ByteArrayInputStream(PasswordPolicyResponseControl.this.encodedValue), bread); new ByteArrayInputStream(PasswordPolicyResponseControl.this.encodedValue), bread);
int size = seq.size(); int size = seq.size();
if (logger.isDebugEnabled()) { if (logger.isDebugEnabled()) {
logger.debug("PasswordPolicyResponse, ASN.1 sequence has " + size + " elements"); logger.debug(LogMessage.format("Received PasswordPolicyResponse whose ASN.1 sequence has %d elements",
size));
} }
for (int i = 0; i < seq.size(); i++) { for (int i = 0; i < seq.size(); i++) {
BERTag elt = (BERTag) seq.elementAt(i); BERTag elt = (BERTag) seq.elementAt(i);

View File

@ -79,8 +79,8 @@ public class FilterBasedLdapUserSearch implements LdapUserSearch {
this.searchBase = searchBase; this.searchBase = searchBase;
setSearchSubtree(true); setSearchSubtree(true);
if (searchBase.length() == 0) { if (searchBase.length() == 0) {
logger.info( logger.info(LogMessage.format("Searches will be performed from the root %s since SearchBase not set",
"SearchBase not set. Searches will be performed from the root: " + contextSource.getBaseLdapPath()); contextSource.getBaseLdapPath()));
} }
} }
@ -93,11 +93,14 @@ public class FilterBasedLdapUserSearch implements LdapUserSearch {
*/ */
@Override @Override
public DirContextOperations searchForUser(String username) { public DirContextOperations searchForUser(String username) {
logger.debug(LogMessage.of(() -> "Searching for user '" + username + "', with user search " + this)); logger.trace(LogMessage.of(() -> "Searching for user '" + username + "', with " + this));
SpringSecurityLdapTemplate template = new SpringSecurityLdapTemplate(this.contextSource); SpringSecurityLdapTemplate template = new SpringSecurityLdapTemplate(this.contextSource);
template.setSearchControls(this.searchControls); template.setSearchControls(this.searchControls);
try { try {
return template.searchForSingleEntry(this.searchBase, this.searchFilter, new String[] { username }); DirContextOperations operations = template.searchForSingleEntry(this.searchBase, this.searchFilter,
new String[] { username });
logger.debug(LogMessage.of(() -> "Found user '" + username + "', with " + this));
return operations;
} }
catch (IncorrectResultSizeDataAccessException ex) { catch (IncorrectResultSizeDataAccessException ex) {
if (ex.getActualSize() == 0) { if (ex.getActualSize() == 0) {
@ -151,12 +154,14 @@ public class FilterBasedLdapUserSearch implements LdapUserSearch {
@Override @Override
public String toString() { public String toString() {
StringBuilder sb = new StringBuilder(); StringBuilder sb = new StringBuilder();
sb.append("[ searchFilter: '").append(this.searchFilter).append("', "); sb.append(getClass().getSimpleName()).append(" [");
sb.append("searchBase: '").append(this.searchBase).append("'"); sb.append("searchFilter=").append(this.searchFilter).append("; ");
sb.append(", scope: ").append( sb.append("searchBase=").append(this.searchBase).append("; ");
(this.searchControls.getSearchScope() != SearchControls.SUBTREE_SCOPE) ? "single-level, " : "subtree"); sb.append("scope=").append(
sb.append(", searchTimeLimit: ").append(this.searchControls.getTimeLimit()); (this.searchControls.getSearchScope() != SearchControls.SUBTREE_SCOPE) ? "single-level" : "subtree")
sb.append(", derefLinkFlag: ").append(this.searchControls.getDerefLinkFlag()).append(" ]"); .append("; ");
sb.append("searchTimeLimit=").append(this.searchControls.getTimeLimit()).append("; ");
sb.append("derefLinkFlag=").append(this.searchControls.getDerefLinkFlag()).append(" ]");
return sb.toString(); return sb.toString();
} }

View File

@ -163,10 +163,10 @@ public class DefaultLdapAuthoritiesPopulator implements LdapAuthoritiesPopulator
getLdapTemplate().setSearchControls(getSearchControls()); getLdapTemplate().setSearchControls(getSearchControls());
this.groupSearchBase = groupSearchBase; this.groupSearchBase = groupSearchBase;
if (groupSearchBase == null) { if (groupSearchBase == null) {
logger.info("groupSearchBase is null. No group search will be performed."); logger.info("Will not perform group search since groupSearchBase is null.");
} }
else if (groupSearchBase.length() == 0) { else if (groupSearchBase.length() == 0) {
logger.info("groupSearchBase is empty. Searches will be performed from the context source base"); logger.info("Will perform group search from the context source base since groupSearchBase is empty.");
} }
this.authorityMapper = (record) -> { this.authorityMapper = (record) -> {
String role = record.get(this.groupRoleAttribute).get(0); String role = record.get(this.groupRoleAttribute).get(0);
@ -199,7 +199,6 @@ public class DefaultLdapAuthoritiesPopulator implements LdapAuthoritiesPopulator
@Override @Override
public final Collection<GrantedAuthority> getGrantedAuthorities(DirContextOperations user, String username) { public final Collection<GrantedAuthority> getGrantedAuthorities(DirContextOperations user, String username) {
String userDn = user.getNameInNamespace(); String userDn = user.getNameInNamespace();
logger.debug(LogMessage.format("Getting authorities for user %s", userDn));
Set<GrantedAuthority> roles = getGroupMembershipRoles(userDn, username); Set<GrantedAuthority> roles = getGroupMembershipRoles(userDn, username);
Set<GrantedAuthority> extraRoles = getAdditionalRoles(user, username); Set<GrantedAuthority> extraRoles = getAdditionalRoles(user, username);
if (extraRoles != null) { if (extraRoles != null) {
@ -210,6 +209,7 @@ public class DefaultLdapAuthoritiesPopulator implements LdapAuthoritiesPopulator
} }
List<GrantedAuthority> result = new ArrayList<>(roles.size()); List<GrantedAuthority> result = new ArrayList<>(roles.size());
result.addAll(roles); result.addAll(roles);
logger.debug(LogMessage.format("Retrieved authorities for user %s", userDn));
return result; return result;
} }
@ -218,12 +218,12 @@ public class DefaultLdapAuthoritiesPopulator implements LdapAuthoritiesPopulator
return new HashSet<>(); return new HashSet<>();
} }
Set<GrantedAuthority> authorities = new HashSet<>(); Set<GrantedAuthority> authorities = new HashSet<>();
logger.debug(LogMessage.of(() -> "Searching for roles for user '" + username + "', DN = " + "'" + userDn logger.trace(LogMessage.of(() -> "Searching for roles for user " + username + " with DN " + userDn
+ "', with filter " + this.groupSearchFilter + " in search base '" + getGroupSearchBase() + "'")); + " and filter " + this.groupSearchFilter + " in search base " + getGroupSearchBase()));
Set<Map<String, List<String>>> userRoles = getLdapTemplate().searchForMultipleAttributeValues( Set<Map<String, List<String>>> userRoles = getLdapTemplate().searchForMultipleAttributeValues(
getGroupSearchBase(), this.groupSearchFilter, new String[] { userDn, username }, getGroupSearchBase(), this.groupSearchFilter, new String[] { userDn, username },
new String[] { this.groupRoleAttribute }); new String[] { this.groupRoleAttribute });
logger.debug(LogMessage.of(() -> "Roles from search: " + userRoles)); logger.debug(LogMessage.of(() -> "Found roles from search " + userRoles));
for (Map<String, List<String>> role : userRoles) { for (Map<String, List<String>> role : userRoles) {
authorities.add(this.authorityMapper.apply(role)); authorities.add(this.authorityMapper.apply(role));
} }

View File

@ -146,30 +146,16 @@ public class LdapUserDetailsImpl implements LdapUserDetails, PasswordPolicyData
@Override @Override
public String toString() { public String toString() {
StringBuilder sb = new StringBuilder(); StringBuilder sb = new StringBuilder();
sb.append(super.toString()).append(": "); sb.append(getClass().getSimpleName()).append(" [");
sb.append("Dn: ").append(this.dn).append("; "); sb.append("Dn=").append(this.dn).append("; ");
sb.append("Username: ").append(this.username).append("; "); sb.append("Username=").append(this.username).append("; ");
sb.append("Password: [PROTECTED]; "); sb.append("Password=[PROTECTED]; ");
sb.append("Enabled: ").append(this.enabled).append("; "); sb.append("Enabled=").append(this.enabled).append("; ");
sb.append("AccountNonExpired: ").append(this.accountNonExpired).append("; "); sb.append("AccountNonExpired=").append(this.accountNonExpired).append("; ");
sb.append("CredentialsNonExpired: ").append(this.credentialsNonExpired).append("; "); sb.append("CredentialsNonExpired=").append(this.credentialsNonExpired).append("; ");
sb.append("AccountNonLocked: ").append(this.accountNonLocked).append("; "); sb.append("AccountNonLocked=").append(this.accountNonLocked).append("; ");
if (this.getAuthorities() != null && !this.getAuthorities().isEmpty()) { sb.append("Granted Authorities=").append(getAuthorities());
sb.append("Granted Authorities: "); sb.append("]");
boolean first = true;
for (Object authority : this.getAuthorities()) {
if (first) {
first = false;
}
else {
sb.append(", ");
}
sb.append(authority.toString());
}
}
else {
sb.append("Not granted any authorities");
}
return sb.toString(); return sb.toString();
} }

View File

@ -54,7 +54,7 @@ public class LdapUserDetailsMapper implements UserDetailsContextMapper {
public UserDetails mapUserFromContext(DirContextOperations ctx, String username, public UserDetails mapUserFromContext(DirContextOperations ctx, String username,
Collection<? extends GrantedAuthority> authorities) { Collection<? extends GrantedAuthority> authorities) {
String dn = ctx.getNameInNamespace(); String dn = ctx.getNameInNamespace();
this.logger.debug(LogMessage.format("Mapping user details from context with DN: %s", dn)); this.logger.debug(LogMessage.format("Mapping user details from context with DN %s", dn));
LdapUserDetailsImpl.Essence essence = new LdapUserDetailsImpl.Essence(); LdapUserDetailsImpl.Essence essence = new LdapUserDetailsImpl.Essence();
essence.setDn(dn); essence.setDn(dn);
Object passwordValue = ctx.getObjectAttribute(this.passwordAttributeName); Object passwordValue = ctx.getObjectAttribute(this.passwordAttributeName);
@ -67,7 +67,7 @@ public class LdapUserDetailsMapper implements UserDetailsContextMapper {
String[] rolesForAttribute = ctx.getStringAttributes(this.roleAttributes[i]); String[] rolesForAttribute = ctx.getStringAttributes(this.roleAttributes[i]);
if (rolesForAttribute == null) { if (rolesForAttribute == null) {
this.logger.debug( this.logger.debug(
LogMessage.format("Couldn't read role attribute '%s' for user $s", this.roleAttributes[i], dn)); LogMessage.format("Couldn't read role attribute %s for user %s", this.roleAttributes[i], dn));
continue; continue;
} }
for (String role : rolesForAttribute) { for (String role : rolesForAttribute) {

View File

@ -166,13 +166,13 @@ public class NestedLdapAuthoritiesPopulator extends DefaultLdapAuthoritiesPopula
private void performNestedSearch(String userDn, String username, Set<GrantedAuthority> authorities, int depth) { private void performNestedSearch(String userDn, String username, Set<GrantedAuthority> authorities, int depth) {
if (depth == 0) { if (depth == 0) {
// back out of recursion // back out of recursion
logger.debug(LogMessage.of(() -> "Search aborted, max depth reached," + " for roles for user '" + username logger.debug(LogMessage.of(() -> "Aborted search since max depth reached," + " for roles for user '"
+ "', DN = " + "'" + userDn + "', with filter " + getGroupSearchFilter() + " in search base '" + username + " with DN = " + userDn + " and filter " + getGroupSearchFilter() + " in search base '"
+ getGroupSearchBase() + "'")); + getGroupSearchBase() + "'"));
return; return;
} }
logger.debug(LogMessage.of(() -> "Searching for roles for user '" + username + "', DN = " + "'" + userDn logger.trace(LogMessage.of(() -> "Searching for roles for user " + username + " with DN " + userDn
+ "', with filter " + getGroupSearchFilter() + " in search base '" + getGroupSearchBase() + "'")); + " and filter " + getGroupSearchFilter() + " in search base " + getGroupSearchBase()));
if (getAttributeNames() == null) { if (getAttributeNames() == null) {
setAttributeNames(new HashSet<>()); setAttributeNames(new HashSet<>());
} }
@ -182,7 +182,7 @@ public class NestedLdapAuthoritiesPopulator extends DefaultLdapAuthoritiesPopula
Set<Map<String, List<String>>> userRoles = getLdapTemplate().searchForMultipleAttributeValues( Set<Map<String, List<String>>> userRoles = getLdapTemplate().searchForMultipleAttributeValues(
getGroupSearchBase(), getGroupSearchFilter(), new String[] { userDn, username }, getGroupSearchBase(), getGroupSearchFilter(), new String[] { userDn, username },
getAttributeNames().toArray(new String[0])); getAttributeNames().toArray(new String[0]));
logger.debug(LogMessage.format("Roles from search: %s", userRoles)); logger.debug(LogMessage.format("Found roles from search %s", userRoles));
for (Map<String, List<String>> record : userRoles) { for (Map<String, List<String>> record : userRoles) {
boolean circular = false; boolean circular = false;
String dn = record.get(SpringSecurityLdapTemplate.DN_KEY).get(0); String dn = record.get(SpringSecurityLdapTemplate.DN_KEY).get(0);