Restructure LDAP Logs

Issue gh-6311

ldap/src/main/java/org/springframework/security/ldap/DefaultSpringSecurityContextSource.java

@@ -28,6 +28,7 @@ import java.util.StringTokenizer;
 import org.apache.commons.logging.Log;
 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.LdapContextSource;
 import org.springframework.ldap.core.support.SimpleDirContextAuthenticationStrategy;
@@ -72,7 +73,7 @@ public class DefaultSpringSecurityContextSource extends LdapContextSource {
 			String url = tokenizer.nextToken();
 			String urlRootDn = LdapUtils.parseRootDnFromUrl(url);
 			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),
 					"Root DNs must be the same when using multiple URLs");
 			rootDn = (rootDn != null) ? rootDn : urlRootDn;
@@ -89,7 +90,7 @@ public class DefaultSpringSecurityContextSource extends LdapContextSource {
 				// Remove the pooling flag unless authenticating as the 'manager' user.
 				if (!DefaultSpringSecurityContextSource.this.userDn.equals(dn)
 						&& 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);
 				}
 			}

ldap/src/main/java/org/springframework/security/ldap/LdapUtils.java

@@ -53,7 +53,7 @@ public final class LdapUtils {
 			}
 		}
 		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) {
-			logger.error("Failed to close enumeration.", ex);
+			logger.debug("Failed to close enumeration.", ex);
 		}
 	}
 

ldap/src/main/java/org/springframework/security/ldap/SpringSecurityLdapTemplate.java

@@ -166,7 +166,7 @@ public class SpringSecurityLdapTemplate extends LdapTemplate {
 			encodedParams[i] = LdapEncoder.filterEncode(params[i].toString());
 		}
 		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<>();
 		ContextMapper roleMapper = (ctx) -> {
 			DirContextAdapter adapter = (DirContextAdapter) ctx;
@@ -223,7 +223,7 @@ public class SpringSecurityLdapTemplate extends LdapTemplate {
 			String attributeName) {
 		Object[] values = adapter.getObjectAttributes(attributeName);
 		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;
 		}
 		List<String> stringValues = new ArrayList<>();
@@ -233,9 +233,9 @@ public class SpringSecurityLdapTemplate extends LdapTemplate {
 					stringValues.add((String) value);
 				}
 				else {
-					logger.debug(LogMessage.format("Attribute:%s contains a non string value of type[%s]",
-							attributeName, value.getClass()));
 					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 NamingEnumeration<SearchResult> resultsEnum = ctx.search(searchBaseDn, filter, params,
 				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));
 		Set<DirContextOperations> results = new HashSet<>();
 		try {
@@ -284,7 +284,7 @@ public class SpringSecurityLdapTemplate extends LdapTemplate {
 		}
 		catch (PartialResultException ex) {
 			LdapUtils.closeEnumeration(resultsEnum);
-			logger.info("Ignoring PartialResultException");
+			logger.trace("Ignoring PartialResultException");
 		}
 		if (results.size() != 1) {
 			throw new IncorrectResultSizeDataAccessException(1, results.size());

ldap/src/main/java/org/springframework/security/ldap/authentication/AbstractLdapAuthenticationProvider.java

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

ldap/src/main/java/org/springframework/security/ldap/authentication/BindAuthenticator.java

@@ -65,7 +65,7 @@ public class BindAuthenticator extends AbstractLdapAuthenticator {
 		String username = authentication.getName();
 		String password = (String) authentication.getCredentials();
 		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(
 					this.messages.getMessage("BindAuthenticator.emptyPassword", "Empty Password"));
 		}
@@ -76,11 +76,18 @@ public class BindAuthenticator extends AbstractLdapAuthenticator {
 				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
 		// with the returned DN.
 		if (user == null && getUserSearch() != null) {
+			logger.trace("Searching for user using " + getUserSearch());
 			DirContextOperations userFromSearch = getUserSearch().searchForUser(username);
 			user = bindWithDn(userFromSearch.getDn().toString(), username, password, userFromSearch.getAttributes());
+			if (user == null) {
+				logger.debug("Failed to find user using " + getUserSearch());
+			}
 		}
 		if (user == null) {
 			throw new BadCredentialsException(
@@ -98,13 +105,12 @@ public class BindAuthenticator extends AbstractLdapAuthenticator {
 		DistinguishedName userDn = new DistinguishedName(userDnStr);
 		DistinguishedName fullDn = new DistinguishedName(userDn);
 		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;
 		try {
 			ctx = getContextSource().getContext(fullDn.toString(), password);
 			// Check for password policy control
 			PasswordPolicyControl ppolicy = PasswordPolicyControlExtractor.extractControl(ctx);
-			logger.debug("Retrieving attributes...");
 			if (attrs == null || attrs.size() == 0) {
 				attrs = ctx.getAttributes(userDn, getUserAttributes());
 			}
@@ -112,6 +118,7 @@ public class BindAuthenticator extends AbstractLdapAuthenticator {
 			if (ppolicy != null) {
 				result.setAttributeValue(ppolicy.getID(), ppolicy);
 			}
+			logger.debug(LogMessage.format("Bound %s", fullDn));
 			return result;
 		}
 		catch (NamingException ex) {
@@ -141,7 +148,7 @@ public class BindAuthenticator extends AbstractLdapAuthenticator {
 	 * logger.
 	 */
 	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);
 	}
 
 }

ldap/src/main/java/org/springframework/security/ldap/authentication/PasswordComparisonAuthenticator.java

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

ldap/src/main/java/org/springframework/security/ldap/authentication/SpringSecurityAuthenticationSource.java

@@ -48,7 +48,7 @@ public class SpringSecurityAuthenticationSource implements AuthenticationSource
 	public String getPrincipal() {
 		Authentication authentication = SecurityContextHolder.getContext().getAuthentication();
 		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 "";
 		}
 		Object principal = authentication.getPrincipal();
@@ -57,7 +57,7 @@ public class SpringSecurityAuthenticationSource implements AuthenticationSource
 			return details.getDn();
 		}
 		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 "";
 		}
 		throw new IllegalArgumentException(
@@ -71,7 +71,7 @@ public class SpringSecurityAuthenticationSource implements AuthenticationSource
 	public String getCredentials() {
 		Authentication authentication = SecurityContextHolder.getContext().getAuthentication();
 		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 (String) authentication.getCredentials();

ldap/src/main/java/org/springframework/security/ldap/ppolicy/PasswordPolicyAwareContextSource.java

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

ldap/src/main/java/org/springframework/security/ldap/ppolicy/PasswordPolicyControlExtractor.java

@@ -43,7 +43,7 @@ public final class PasswordPolicyControlExtractor {
 			ctrls = ctx.getResponseControls();
 		}
 		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++) {
 			if (ctrls[i] instanceof PasswordPolicyResponseControl) {

ldap/src/main/java/org/springframework/security/ldap/ppolicy/PasswordPolicyResponseControl.java

@@ -31,6 +31,7 @@ import netscape.ldap.ber.stream.BERTagDecoder;
 import org.apache.commons.logging.Log;
 import org.apache.commons.logging.LogFactory;
 
+import org.springframework.core.log.LogMessage;
 import org.springframework.dao.DataRetrievalFailureException;
 
 /**
@@ -158,19 +159,21 @@ public class PasswordPolicyResponseControl extends PasswordPolicyControl {
 	 */
 	@Override
 	public String toString() {
-		StringBuilder sb = new StringBuilder("PasswordPolicyResponseControl");
+		StringBuilder sb = new StringBuilder();
+		sb.append(getClass().getSimpleName()).append(" [");
 		if (hasError()) {
-			sb.append(", error: ").append(this.errorStatus.getDefaultMessage());
+			sb.append("error=").append(this.errorStatus.getDefaultMessage()).append("; ");
 		}
 		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) {
-			sb.append(", warning: time before expiration is ").append(this.timeBeforeExpiration);
+			sb.append("warning=time before expiration is ").append(this.timeBeforeExpiration).append("; ");
 		}
 		if (!hasError() && !hasWarning()) {
-			sb.append(" (no error, no warning)");
+			sb.append("(no error, no warning)");
 		}
+		sb.append("]");
 		return sb.toString();
 	}
 
@@ -192,7 +195,8 @@ public class PasswordPolicyResponseControl extends PasswordPolicyControl {
 					new ByteArrayInputStream(PasswordPolicyResponseControl.this.encodedValue), bread);
 			int size = seq.size();
 			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++) {
 				BERTag elt = (BERTag) seq.elementAt(i);

ldap/src/main/java/org/springframework/security/ldap/search/FilterBasedLdapUserSearch.java

@@ -79,8 +79,8 @@ public class FilterBasedLdapUserSearch implements LdapUserSearch {
 		this.searchBase = searchBase;
 		setSearchSubtree(true);
 		if (searchBase.length() == 0) {
-			logger.info(
-					"SearchBase not set. Searches will be performed from the root: " + contextSource.getBaseLdapPath());
+			logger.info(LogMessage.format("Searches will be performed from the root %s since SearchBase not set",
+					contextSource.getBaseLdapPath()));
 		}
 	}
 
@@ -93,11 +93,14 @@ public class FilterBasedLdapUserSearch implements LdapUserSearch {
 	 */
 	@Override
 	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);
 		template.setSearchControls(this.searchControls);
 		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) {
 			if (ex.getActualSize() == 0) {
@@ -151,12 +154,14 @@ public class FilterBasedLdapUserSearch implements LdapUserSearch {
 	@Override
 	public String toString() {
 		StringBuilder sb = new StringBuilder();
-		sb.append("[ searchFilter: '").append(this.searchFilter).append("', ");
-		sb.append("searchBase: '").append(this.searchBase).append("'");
-		sb.append(", scope: ").append(
-				(this.searchControls.getSearchScope() != SearchControls.SUBTREE_SCOPE) ? "single-level, " : "subtree");
-		sb.append(", searchTimeLimit: ").append(this.searchControls.getTimeLimit());
-		sb.append(", derefLinkFlag: ").append(this.searchControls.getDerefLinkFlag()).append(" ]");
+		sb.append(getClass().getSimpleName()).append(" [");
+		sb.append("searchFilter=").append(this.searchFilter).append("; ");
+		sb.append("searchBase=").append(this.searchBase).append("; ");
+		sb.append("scope=").append(
+				(this.searchControls.getSearchScope() != SearchControls.SUBTREE_SCOPE) ? "single-level" : "subtree")
+				.append("; ");
+		sb.append("searchTimeLimit=").append(this.searchControls.getTimeLimit()).append("; ");
+		sb.append("derefLinkFlag=").append(this.searchControls.getDerefLinkFlag()).append(" ]");
 		return sb.toString();
 	}
 

ldap/src/main/java/org/springframework/security/ldap/userdetails/DefaultLdapAuthoritiesPopulator.java

@@ -163,10 +163,10 @@ public class DefaultLdapAuthoritiesPopulator implements LdapAuthoritiesPopulator
 		getLdapTemplate().setSearchControls(getSearchControls());
 		this.groupSearchBase = groupSearchBase;
 		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) {
-			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) -> {
 			String role = record.get(this.groupRoleAttribute).get(0);
@@ -199,7 +199,6 @@ public class DefaultLdapAuthoritiesPopulator implements LdapAuthoritiesPopulator
 	@Override
 	public final Collection<GrantedAuthority> getGrantedAuthorities(DirContextOperations user, String username) {
 		String userDn = user.getNameInNamespace();
-		logger.debug(LogMessage.format("Getting authorities for user %s", userDn));
 		Set<GrantedAuthority> roles = getGroupMembershipRoles(userDn, username);
 		Set<GrantedAuthority> extraRoles = getAdditionalRoles(user, username);
 		if (extraRoles != null) {
@@ -210,6 +209,7 @@ public class DefaultLdapAuthoritiesPopulator implements LdapAuthoritiesPopulator
 		}
 		List<GrantedAuthority> result = new ArrayList<>(roles.size());
 		result.addAll(roles);
+		logger.debug(LogMessage.format("Retrieved authorities for user %s", userDn));
 		return result;
 	}
 
@@ -218,12 +218,12 @@ public class DefaultLdapAuthoritiesPopulator implements LdapAuthoritiesPopulator
 			return new HashSet<>();
 		}
 		Set<GrantedAuthority> authorities = new HashSet<>();
-		logger.debug(LogMessage.of(() -> "Searching for roles for user '" + username + "', DN = " + "'" + userDn
-				+ "', with filter " + this.groupSearchFilter + " in search base '" + getGroupSearchBase() + "'"));
+		logger.trace(LogMessage.of(() -> "Searching for roles for user " + username + " with DN " + userDn
+				+ " and filter " + this.groupSearchFilter + " in search base " + getGroupSearchBase()));
 		Set<Map<String, List<String>>> userRoles = getLdapTemplate().searchForMultipleAttributeValues(
 				getGroupSearchBase(), this.groupSearchFilter, new String[] { userDn, username },
 				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) {
 			authorities.add(this.authorityMapper.apply(role));
 		}

ldap/src/main/java/org/springframework/security/ldap/userdetails/LdapUserDetailsImpl.java

@@ -146,30 +146,16 @@ public class LdapUserDetailsImpl implements LdapUserDetails, PasswordPolicyData
 	@Override
 	public String toString() {
 		StringBuilder sb = new StringBuilder();
-		sb.append(super.toString()).append(": ");
-		sb.append("Dn: ").append(this.dn).append("; ");
-		sb.append("Username: ").append(this.username).append("; ");
-		sb.append("Password: [PROTECTED]; ");
-		sb.append("Enabled: ").append(this.enabled).append("; ");
-		sb.append("AccountNonExpired: ").append(this.accountNonExpired).append("; ");
-		sb.append("CredentialsNonExpired: ").append(this.credentialsNonExpired).append("; ");
-		sb.append("AccountNonLocked: ").append(this.accountNonLocked).append("; ");
-		if (this.getAuthorities() != null && !this.getAuthorities().isEmpty()) {
-			sb.append("Granted Authorities: ");
-			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");
-		}
+		sb.append(getClass().getSimpleName()).append(" [");
+		sb.append("Dn=").append(this.dn).append("; ");
+		sb.append("Username=").append(this.username).append("; ");
+		sb.append("Password=[PROTECTED]; ");
+		sb.append("Enabled=").append(this.enabled).append("; ");
+		sb.append("AccountNonExpired=").append(this.accountNonExpired).append("; ");
+		sb.append("CredentialsNonExpired=").append(this.credentialsNonExpired).append("; ");
+		sb.append("AccountNonLocked=").append(this.accountNonLocked).append("; ");
+		sb.append("Granted Authorities=").append(getAuthorities());
+		sb.append("]");
 		return sb.toString();
 	}
 

ldap/src/main/java/org/springframework/security/ldap/userdetails/LdapUserDetailsMapper.java

@@ -54,7 +54,7 @@ public class LdapUserDetailsMapper implements UserDetailsContextMapper {
 	public UserDetails mapUserFromContext(DirContextOperations ctx, String username,
 			Collection<? extends GrantedAuthority> authorities) {
 		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();
 		essence.setDn(dn);
 		Object passwordValue = ctx.getObjectAttribute(this.passwordAttributeName);
@@ -67,7 +67,7 @@ public class LdapUserDetailsMapper implements UserDetailsContextMapper {
 			String[] rolesForAttribute = ctx.getStringAttributes(this.roleAttributes[i]);
 			if (rolesForAttribute == null) {
 				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;
 			}
 			for (String role : rolesForAttribute) {

ldap/src/main/java/org/springframework/security/ldap/userdetails/NestedLdapAuthoritiesPopulator.java

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