Skip to content

Commit 3a3b285

Browse files
jzheauxjzheaux
committed
Restructure LDAP Logs
Issue gh-6311
1 parent 5019653 commit 3a3b285

15 files changed

+92
-81
lines changed

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

+3-2
Original file line numberDiff line numberDiff line change
@@ -28,6 +28,7 @@
2828
import org.apache.commons.logging.Log;
2929
import org.apache.commons.logging.LogFactory;
3030

31+
import org.springframework.core.log.LogMessage;
3132
import org.springframework.ldap.core.support.DirContextAuthenticationStrategy;
3233
import org.springframework.ldap.core.support.LdapContextSource;
3334
import org.springframework.ldap.core.support.SimpleDirContextAuthenticationStrategy;
@@ -72,7 +73,7 @@ public DefaultSpringSecurityContextSource(String providerUrl) {
7273
String url = tokenizer.nextToken();
7374
String urlRootDn = LdapUtils.parseRootDnFromUrl(url);
7475
urls.add(url.substring(0, url.lastIndexOf(urlRootDn)));
75-
this.logger.info(" URL '" + url + "', root DN is '" + urlRootDn + "'");
76+
this.logger.info(LogMessage.format("Configure with URL %s and root DN %s", url, urlRootDn));
7677
Assert.isTrue(rootDn == null || rootDn.equals(urlRootDn),
7778
"Root DNs must be the same when using multiple URLs");
7879
rootDn = (rootDn != null) ? rootDn : urlRootDn;
@@ -89,7 +90,7 @@ public void setupEnvironment(Hashtable env, String dn, String password) {
8990
// Remove the pooling flag unless authenticating as the 'manager' user.
9091
if (!DefaultSpringSecurityContextSource.this.userDn.equals(dn)
9192
&& env.containsKey(SUN_LDAP_POOLING_FLAG)) {
92-
DefaultSpringSecurityContextSource.this.logger.debug("Removing pooling flag for user " + dn);
93+
DefaultSpringSecurityContextSource.this.logger.trace("Removing pooling flag for user " + dn);
9394
env.remove(SUN_LDAP_POOLING_FLAG);
9495
}
9596
}

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

+2-2
Original file line numberDiff line numberDiff line change
@@ -53,7 +53,7 @@ public static void closeContext(Context ctx) {
5353
}
5454
}
5555
catch (NamingException ex) {
56-
logger.error("Failed to close context.", ex);
56+
logger.debug("Failed to close context.", ex);
5757
}
5858
}
5959

@@ -64,7 +64,7 @@ public static void closeEnumeration(NamingEnumeration ne) {
6464
}
6565
}
6666
catch (NamingException ex) {
67-
logger.error("Failed to close enumeration.", ex);
67+
logger.debug("Failed to close enumeration.", ex);
6868
}
6969
}
7070

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

+6-6
Original file line numberDiff line numberDiff line change
@@ -166,7 +166,7 @@ public Set<Map<String, List<String>>> searchForMultipleAttributeValues(String ba
166166
encodedParams[i] = LdapEncoder.filterEncode(params[i].toString());
167167
}
168168
String formattedFilter = MessageFormat.format(filter, encodedParams);
169-
logger.debug(LogMessage.format("Using filter: %s", formattedFilter));
169+
logger.trace(LogMessage.format("Using filter: %s", formattedFilter));
170170
HashSet<Map<String, List<String>>> result = new HashSet<>();
171171
ContextMapper roleMapper = (ctx) -> {
172172
DirContextAdapter adapter = (DirContextAdapter) ctx;
@@ -223,7 +223,7 @@ private void extractStringAttributeValues(DirContextAdapter adapter, Map<String,
223223
String attributeName) {
224224
Object[] values = adapter.getObjectAttributes(attributeName);
225225
if (values == null || values.length == 0) {
226-
logger.debug(LogMessage.format("No attribute value found for '%s'", attributeName));
226+
logger.debug(LogMessage.format("Did not find attribute value for %s", attributeName));
227227
return;
228228
}
229229
List<String> stringValues = new ArrayList<>();
@@ -233,9 +233,9 @@ private void extractStringAttributeValues(DirContextAdapter adapter, Map<String,
233233
stringValues.add((String) value);
234234
}
235235
else {
236-
logger.debug(LogMessage.format("Attribute:%s contains a non string value of type[%s]",
237-
attributeName, value.getClass()));
238236
stringValues.add(value.toString());
237+
logger.debug(LogMessage.format("Coerced attribute value for %s of type %s to a String",
238+
attributeName, value.getClass()));
239239
}
240240
}
241241
}
@@ -270,7 +270,7 @@ public static DirContextOperations searchForSingleEntryInternal(DirContext ctx,
270270
final DistinguishedName searchBaseDn = new DistinguishedName(base);
271271
final NamingEnumeration<SearchResult> resultsEnum = ctx.search(searchBaseDn, filter, params,
272272
buildControls(searchControls));
273-
logger.debug(LogMessage.format("Searching for entry under DN '%s', base = '%s', filter = '%s'", ctxBaseDn,
273+
logger.trace(LogMessage.format("Searching for entry under DN '%s', base = '%s', filter = '%s'", ctxBaseDn,
274274
searchBaseDn, filter));
275275
Set<DirContextOperations> results = new HashSet<>();
276276
try {
@@ -284,7 +284,7 @@ public static DirContextOperations searchForSingleEntryInternal(DirContext ctx,
284284
}
285285
catch (PartialResultException ex) {
286286
LdapUtils.closeEnumeration(resultsEnum);
287-
logger.info("Ignoring PartialResultException");
287+
logger.trace("Ignoring PartialResultException");
288288
}
289289
if (results.size() != 1) {
290290
throw new IncorrectResultSizeDataAccessException(1, results.size());

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

+1-2
Original file line numberDiff line numberDiff line change
@@ -24,7 +24,6 @@
2424
import org.springframework.context.MessageSource;
2525
import org.springframework.context.MessageSourceAware;
2626
import org.springframework.context.support.MessageSourceAccessor;
27-
import org.springframework.core.log.LogMessage;
2827
import org.springframework.ldap.core.DirContextOperations;
2928
import org.springframework.security.authentication.AuthenticationProvider;
3029
import org.springframework.security.authentication.BadCredentialsException;
@@ -68,7 +67,6 @@ public Authentication authenticate(Authentication authentication) throws Authent
6867
UsernamePasswordAuthenticationToken userToken = (UsernamePasswordAuthenticationToken) authentication;
6968
String username = userToken.getName();
7069
String password = (String) authentication.getCredentials();
71-
this.logger.debug(LogMessage.format("Processing authentication request for user: %s", username));
7270
if (!StringUtils.hasLength(username)) {
7371
throw new BadCredentialsException(
7472
this.messages.getMessage("LdapAuthenticationProvider.emptyUsername", "Empty Username"));
@@ -104,6 +102,7 @@ protected Authentication createSuccessfulAuthentication(UsernamePasswordAuthenti
104102
UsernamePasswordAuthenticationToken result = new UsernamePasswordAuthenticationToken(user, password,
105103
this.authoritiesMapper.mapAuthorities(user.getAuthorities()));
106104
result.setDetails(authentication.getDetails());
105+
this.logger.debug("Authenticated user");
107106
return result;
108107
}
109108

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

+11-4
Original file line numberDiff line numberDiff line change
@@ -65,7 +65,7 @@ public DirContextOperations authenticate(Authentication authentication) {
6565
String username = authentication.getName();
6666
String password = (String) authentication.getCredentials();
6767
if (!StringUtils.hasLength(password)) {
68-
logger.debug(LogMessage.format("Rejecting empty password for user %s", username));
68+
logger.debug(LogMessage.format("Failed to authenticate since no credentials provided"));
6969
throw new BadCredentialsException(
7070
this.messages.getMessage("BindAuthenticator.emptyPassword", "Empty Password"));
7171
}
@@ -76,11 +76,18 @@ public DirContextOperations authenticate(Authentication authentication) {
7676
break;
7777
}
7878
}
79+
if (user == null) {
80+
logger.debug(LogMessage.of(() -> "Failed to bind with any user DNs " + getUserDns(username)));
81+
}
7982
// Otherwise use the configured search object to find the user and authenticate
8083
// with the returned DN.
8184
if (user == null && getUserSearch() != null) {
85+
logger.trace("Searching for user using " + getUserSearch());
8286
DirContextOperations userFromSearch = getUserSearch().searchForUser(username);
8387
user = bindWithDn(userFromSearch.getDn().toString(), username, password, userFromSearch.getAttributes());
88+
if (user == null) {
89+
logger.debug("Failed to find user using " + getUserSearch());
90+
}
8491
}
8592
if (user == null) {
8693
throw new BadCredentialsException(
@@ -98,20 +105,20 @@ private DirContextOperations bindWithDn(String userDnStr, String username, Strin
98105
DistinguishedName userDn = new DistinguishedName(userDnStr);
99106
DistinguishedName fullDn = new DistinguishedName(userDn);
100107
fullDn.prepend(ctxSource.getBaseLdapPath());
101-
logger.debug(LogMessage.format("Attempting to bind as %s", fullDn));
108+
logger.trace(LogMessage.format("Attempting to bind as %s", fullDn));
102109
DirContext ctx = null;
103110
try {
104111
ctx = getContextSource().getContext(fullDn.toString(), password);
105112
// Check for password policy control
106113
PasswordPolicyControl ppolicy = PasswordPolicyControlExtractor.extractControl(ctx);
107-
logger.debug("Retrieving attributes...");
108114
if (attrs == null || attrs.size() == 0) {
109115
attrs = ctx.getAttributes(userDn, getUserAttributes());
110116
}
111117
DirContextAdapter result = new DirContextAdapter(attrs, userDn, ctxSource.getBaseLdapPath());
112118
if (ppolicy != null) {
113119
result.setAttributeValue(ppolicy.getID(), ppolicy);
114120
}
121+
logger.debug(LogMessage.format("Bound %s", fullDn));
115122
return result;
116123
}
117124
catch (NamingException ex) {
@@ -141,7 +148,7 @@ private DirContextOperations bindWithDn(String userDnStr, String username, Strin
141148
* logger.
142149
*/
143150
protected void handleBindException(String userDn, String username, Throwable cause) {
144-
logger.debug(LogMessage.format("Failed to bind as %s: %s", userDn, cause));
151+
logger.trace(LogMessage.format("Failed to bind as %s", userDn), cause);
145152
}
146153

147154
}

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

+14-2
Original file line numberDiff line numberDiff line change
@@ -76,25 +76,37 @@ public DirContextOperations authenticate(final Authentication authentication) {
7676
user = ldapTemplate.retrieveEntry(userDn, getUserAttributes());
7777
}
7878
catch (NameNotFoundException ignore) {
79+
logger.trace(LogMessage.format("Failed to retrieve user with %s", userDn), ignore);
7980
}
8081
if (user != null) {
8182
break;
8283
}
8384
}
85+
if (user == null) {
86+
logger.debug(LogMessage.of(() -> "Failed to retrieve user with any user DNs " + getUserDns(username)));
87+
}
8488
if (user == null && getUserSearch() != null) {
89+
logger.trace("Searching for user using " + getUserSearch());
8590
user = getUserSearch().searchForUser(username);
91+
if (user == null) {
92+
logger.debug("Failed to find user using " + getUserSearch());
93+
}
8694
}
8795
if (user == null) {
8896
throw new UsernameNotFoundException("User not found: " + username);
8997
}
90-
if (logger.isDebugEnabled()) {
91-
logger.debug(LogMessage.format("Performing LDAP compare of password attribute '%s' for user '%s'",
98+
if (logger.isTraceEnabled()) {
99+
logger.trace(LogMessage.format("Comparing password attribute '%s' for user '%s'",
92100
this.passwordAttributeName, user.getDn()));
93101
}
94102
if (this.usePasswordAttrCompare && isPasswordAttrCompare(user, password)) {
103+
logger.debug(LogMessage.format("Locally matched password attribute '%s' for user '%s'",
104+
this.passwordAttributeName, user.getDn()));
95105
return user;
96106
}
97107
if (isLdapPasswordCompare(user, ldapTemplate, password)) {
108+
logger.debug(LogMessage.format("LDAP-matched password attribute '%s' for user '%s'",
109+
this.passwordAttributeName, user.getDn()));
98110
return user;
99111
}
100112
throw new BadCredentialsException(

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

+3-3
Original file line numberDiff line numberDiff line change
@@ -48,7 +48,7 @@ public class SpringSecurityAuthenticationSource implements AuthenticationSource
4848
public String getPrincipal() {
4949
Authentication authentication = SecurityContextHolder.getContext().getAuthentication();
5050
if (authentication == null) {
51-
log.warn("No Authentication object set in SecurityContext - returning empty String as Principal");
51+
log.debug("Returning empty String as Principal since authentication is null");
5252
return "";
5353
}
5454
Object principal = authentication.getPrincipal();
@@ -57,7 +57,7 @@ public String getPrincipal() {
5757
return details.getDn();
5858
}
5959
if (authentication instanceof AnonymousAuthenticationToken) {
60-
log.debug("Anonymous Authentication, returning empty String as Principal");
60+
log.debug("Returning empty String as Principal since authentication is anonymous");
6161
return "";
6262
}
6363
throw new IllegalArgumentException(
@@ -71,7 +71,7 @@ public String getPrincipal() {
7171
public String getCredentials() {
7272
Authentication authentication = SecurityContextHolder.getContext().getAuthentication();
7373
if (authentication == null) {
74-
log.warn("No Authentication object set in SecurityContext - returning empty String as Credentials");
74+
log.debug("Returning empty String as Credentials since authentication is null");
7575
return "";
7676
}
7777
return (String) authentication.getCredentials();

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

+3-6
Original file line numberDiff line numberDiff line change
@@ -50,8 +50,7 @@ public DirContext getContext(String principal, String credentials) throws Passwo
5050
if (principal.equals(this.userDn)) {
5151
return super.getContext(principal, credentials);
5252
}
53-
this.logger
54-
.debug(LogMessage.format("Binding as '%s', prior to reconnect as user '%s'", this.userDn, principal));
53+
this.logger.trace(LogMessage.format("Binding as %s, prior to reconnect as user %s", this.userDn, principal));
5554
// First bind as manager user before rebinding as the specific principal.
5655
LdapContext ctx = (LdapContext) super.getContext(this.userDn, this.password);
5756
Control[] rctls = { new PasswordPolicyControl(false) };
@@ -63,17 +62,15 @@ public DirContext getContext(String principal, String credentials) throws Passwo
6362
catch (javax.naming.NamingException ex) {
6463
PasswordPolicyResponseControl ctrl = PasswordPolicyControlExtractor.extractControl(ctx);
6564
if (this.logger.isDebugEnabled()) {
66-
this.logger.debug("Failed to obtain context", ex);
67-
this.logger.debug("Password policy response: " + ctrl);
65+
this.logger.debug(LogMessage.format("Failed to bind with %s", ctrl), ex);
6866
}
6967
LdapUtils.closeContext(ctx);
7068
if (ctrl != null && ctrl.isLocked()) {
7169
throw new PasswordPolicyException(ctrl.getErrorStatus());
7270
}
7371
throw LdapUtils.convertLdapException(ex);
7472
}
75-
this.logger.debug(
76-
LogMessage.of(() -> "PPolicy control returned: " + PasswordPolicyControlExtractor.extractControl(ctx)));
73+
this.logger.debug(LogMessage.of(() -> "Bound with " + PasswordPolicyControlExtractor.extractControl(ctx)));
7774
return ctx;
7875
}
7976

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

+1-1
Original file line numberDiff line numberDiff line change
@@ -43,7 +43,7 @@ public static PasswordPolicyResponseControl extractControl(DirContext dirCtx) {
4343
ctrls = ctx.getResponseControls();
4444
}
4545
catch (javax.naming.NamingException ex) {
46-
logger.error("Failed to obtain response controls", ex);
46+
logger.trace("Failed to obtain response controls", ex);
4747
}
4848
for (int i = 0; ctrls != null && i < ctrls.length; i++) {
4949
if (ctrls[i] instanceof PasswordPolicyResponseControl) {

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

+10-6
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,7 @@
3131
import org.apache.commons.logging.Log;
3232
import org.apache.commons.logging.LogFactory;
3333

34+
import org.springframework.core.log.LogMessage;
3435
import org.springframework.dao.DataRetrievalFailureException;
3536

3637
/**
@@ -158,19 +159,21 @@ public boolean isLocked() {
158159
*/
159160
@Override
160161
public String toString() {
161-
StringBuilder sb = new StringBuilder("PasswordPolicyResponseControl");
162+
StringBuilder sb = new StringBuilder();
163+
sb.append(getClass().getSimpleName()).append(" [");
162164
if (hasError()) {
163-
sb.append(", error: ").append(this.errorStatus.getDefaultMessage());
165+
sb.append("error=").append(this.errorStatus.getDefaultMessage()).append("; ");
164166
}
165167
if (this.graceLoginsRemaining != Integer.MAX_VALUE) {
166-
sb.append(", warning: ").append(this.graceLoginsRemaining).append(" grace logins remain");
168+
sb.append("warning=").append(this.graceLoginsRemaining).append(" grace logins remain; ");
167169
}
168170
if (this.timeBeforeExpiration != Integer.MAX_VALUE) {
169-
sb.append(", warning: time before expiration is ").append(this.timeBeforeExpiration);
171+
sb.append("warning=time before expiration is ").append(this.timeBeforeExpiration).append("; ");
170172
}
171173
if (!hasError() && !hasWarning()) {
172-
sb.append(" (no error, no warning)");
174+
sb.append("(no error, no warning)");
173175
}
176+
sb.append("]");
174177
return sb.toString();
175178
}
176179

@@ -192,7 +195,8 @@ public void decode() throws IOException {
192195
new ByteArrayInputStream(PasswordPolicyResponseControl.this.encodedValue), bread);
193196
int size = seq.size();
194197
if (logger.isDebugEnabled()) {
195-
logger.debug("PasswordPolicyResponse, ASN.1 sequence has " + size + " elements");
198+
logger.debug(LogMessage.format("Received PasswordPolicyResponse whose ASN.1 sequence has %d elements",
199+
size));
196200
}
197201
for (int i = 0; i < seq.size(); i++) {
198202
BERTag elt = (BERTag) seq.elementAt(i);

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

+15-10
Original file line numberDiff line numberDiff line change
@@ -79,8 +79,8 @@ public FilterBasedLdapUserSearch(String searchBase, String searchFilter, BaseLda
7979
this.searchBase = searchBase;
8080
setSearchSubtree(true);
8181
if (searchBase.length() == 0) {
82-
logger.info(
83-
"SearchBase not set. Searches will be performed from the root: " + contextSource.getBaseLdapPath());
82+
logger.info(LogMessage.format("Searches will be performed from the root %s since SearchBase not set",
83+
contextSource.getBaseLdapPath()));
8484
}
8585
}
8686

@@ -93,11 +93,14 @@ public FilterBasedLdapUserSearch(String searchBase, String searchFilter, BaseLda
9393
*/
9494
@Override
9595
public DirContextOperations searchForUser(String username) {
96-
logger.debug(LogMessage.of(() -> "Searching for user '" + username + "', with user search " + this));
96+
logger.trace(LogMessage.of(() -> "Searching for user '" + username + "', with " + this));
9797
SpringSecurityLdapTemplate template = new SpringSecurityLdapTemplate(this.contextSource);
9898
template.setSearchControls(this.searchControls);
9999
try {
100-
return template.searchForSingleEntry(this.searchBase, this.searchFilter, new String[] { username });
100+
DirContextOperations operations = template.searchForSingleEntry(this.searchBase, this.searchFilter,
101+
new String[] { username });
102+
logger.debug(LogMessage.of(() -> "Found user '" + username + "', with " + this));
103+
return operations;
101104
}
102105
catch (IncorrectResultSizeDataAccessException ex) {
103106
if (ex.getActualSize() == 0) {
@@ -151,12 +154,14 @@ public void setReturningAttributes(String[] attrs) {
151154
@Override
152155
public String toString() {
153156
StringBuilder sb = new StringBuilder();
154-
sb.append("[ searchFilter: '").append(this.searchFilter).append("', ");
155-
sb.append("searchBase: '").append(this.searchBase).append("'");
156-
sb.append(", scope: ").append(
157-
(this.searchControls.getSearchScope() != SearchControls.SUBTREE_SCOPE) ? "single-level, " : "subtree");
158-
sb.append(", searchTimeLimit: ").append(this.searchControls.getTimeLimit());
159-
sb.append(", derefLinkFlag: ").append(this.searchControls.getDerefLinkFlag()).append(" ]");
157+
sb.append(getClass().getSimpleName()).append(" [");
158+
sb.append("searchFilter=").append(this.searchFilter).append("; ");
159+
sb.append("searchBase=").append(this.searchBase).append("; ");
160+
sb.append("scope=").append(
161+
(this.searchControls.getSearchScope() != SearchControls.SUBTREE_SCOPE) ? "single-level" : "subtree")
162+
.append("; ");
163+
sb.append("searchTimeLimit=").append(this.searchControls.getTimeLimit()).append("; ");
164+
sb.append("derefLinkFlag=").append(this.searchControls.getDerefLinkFlag()).append(" ]");
160165
return sb.toString();
161166
}
162167

0 commit comments

Comments
 (0)