Restructure Logs

Followed common use cases based off of HelloWorld sample:
  - Public endpoint
  - Unauthorized endpoint
  - Undefined endpoint
  - Successful form login
  - Failed form login
  - Post-login redirect

Issue gh-6311
This commit is contained in:
Josh Cummings
2020-06-09 09:47:49 -06:00
parent 17f1540280
commit fa7baf551d
54 changed files with 386 additions and 211 deletions

View File

@@ -167,9 +167,13 @@ public abstract class AbstractSecurityInterceptor
}
}
if (unsupportedAttrs.size() != 0) {
this.logger
.trace("Did not validate configuration attributes since validateConfigurationAttributes is false");
throw new IllegalArgumentException("Unsupported configuration attributes: " + unsupportedAttrs);
}
this.logger.debug("Validated configuration attributes");
else {
this.logger.trace("Validated configuration attributes");
}
}
protected InterceptorStatusToken beforeInvocation(Object object) {
@@ -186,19 +190,25 @@ public abstract class AbstractSecurityInterceptor
+ " was denied as public invocations are not allowed via this interceptor. "
+ "This indicates a configuration error because the "
+ "rejectPublicInvocations property is set to 'true'");
this.logger.debug("Public object - authentication not attempted");
if (this.logger.isDebugEnabled()) {
this.logger.debug(LogMessage.format("Authorized public object %s", object));
}
publishEvent(new PublicInvocationEvent(object));
return null; // no further work post-invocation
}
this.logger.debug(LogMessage.format("Secure object: %s; Attributes: %s", object, attributes));
if (SecurityContextHolder.getContext().getAuthentication() == null) {
credentialsNotFound(this.messages.getMessage("AbstractSecurityInterceptor.authenticationNotFound",
"An Authentication object was not found in the SecurityContext"), object, attributes);
}
Authentication authenticated = authenticateIfRequired();
if (this.logger.isTraceEnabled()) {
this.logger.trace(LogMessage.format("Authorizing %s with attributes %s", object, attributes));
}
// Attempt authorization
attemptAuthorization(object, attributes, authenticated);
this.logger.debug("Authorization successful");
if (this.logger.isDebugEnabled()) {
this.logger.debug(LogMessage.format("Authorized %s with attributes %s", object, attributes));
}
if (this.publishAuthorizationSuccess) {
publishEvent(new AuthorizedEvent(object, attributes, authenticated));
}
@@ -206,14 +216,17 @@ public abstract class AbstractSecurityInterceptor
// Attempt to run as a different user
Authentication runAs = this.runAsManager.buildRunAs(authenticated, object, attributes);
if (runAs != null) {
this.logger.debug(LogMessage.format("Switching to RunAs Authentication: %s", runAs));
SecurityContext origCtx = SecurityContextHolder.getContext();
SecurityContextHolder.setContext(SecurityContextHolder.createEmptyContext());
SecurityContextHolder.getContext().setAuthentication(runAs);
if (this.logger.isDebugEnabled()) {
this.logger.debug(LogMessage.format("Switched to RunAs authentication %s", runAs));
}
// need to revert to token.Authenticated post-invocation
return new InterceptorStatusToken(origCtx, true, attributes, object);
}
this.logger.debug("RunAsManager did not change Authentication object");
this.logger.trace("Did not switch RunAs authentication since RunAsManager returned null");
// no further work post-invocation
return new InterceptorStatusToken(SecurityContextHolder.getContext(), false, attributes, object);
@@ -225,6 +238,13 @@ public abstract class AbstractSecurityInterceptor
this.accessDecisionManager.decide(authenticated, object, attributes);
}
catch (AccessDeniedException ex) {
if (this.logger.isTraceEnabled()) {
this.logger.trace(LogMessage.format("Failed to authorize %s with attributes %s using %s", object,
attributes, this.accessDecisionManager));
}
else if (this.logger.isDebugEnabled()) {
this.logger.debug(LogMessage.format("Failed to authorize %s with attributes %s", object, attributes));
}
publishEvent(new AuthorizationFailureEvent(object, attributes, authenticated, ex));
throw ex;
}
@@ -239,9 +259,11 @@ public abstract class AbstractSecurityInterceptor
*/
protected void finallyInvocation(InterceptorStatusToken token) {
if (token != null && token.isContextHolderRefreshRequired()) {
this.logger.debug(LogMessage.of(
() -> "Reverting to original Authentication: " + token.getSecurityContext().getAuthentication()));
SecurityContextHolder.setContext(token.getSecurityContext());
if (this.logger.isDebugEnabled()) {
this.logger.debug(LogMessage.of(
() -> "Reverted to original authentication " + token.getSecurityContext().getAuthentication()));
}
}
}
@@ -284,12 +306,16 @@ public abstract class AbstractSecurityInterceptor
private Authentication authenticateIfRequired() {
Authentication authentication = SecurityContextHolder.getContext().getAuthentication();
if (authentication.isAuthenticated() && !this.alwaysReauthenticate) {
this.logger.debug(LogMessage.format("Previously Authenticated: %s", authentication));
if (this.logger.isTraceEnabled()) {
this.logger.trace(LogMessage.format("Did not re-authenticate %s before authorizing", authentication));
}
return authentication;
}
authentication = this.authenticationManager.authenticate(authentication);
// Don't authenticated.setAuthentication(true) because each provider does that
this.logger.debug(LogMessage.format("Successfully Authenticated: %s", authentication));
if (this.logger.isDebugEnabled()) {
this.logger.debug(LogMessage.format("Re-authenticated %s before authorizing", authentication));
}
SecurityContextHolder.getContext().setAuthentication(authentication);
return authentication;
}

View File

@@ -115,4 +115,10 @@ public abstract class AbstractAccessDecisionManager
return true;
}
@Override
public String toString() {
return this.getClass().getSimpleName() + " [DecisionVoters=" + this.decisionVoters
+ ", AllowIfAllAbstainDecisions=" + this.allowIfAllAbstainDecisions + "]";
}
}

View File

@@ -19,7 +19,6 @@ package org.springframework.security.access.vote;
import java.util.Collection;
import java.util.List;
import org.springframework.core.log.LogMessage;
import org.springframework.security.access.AccessDecisionVoter;
import org.springframework.security.access.AccessDeniedException;
import org.springframework.security.access.ConfigAttribute;
@@ -59,7 +58,6 @@ public class AffirmativeBased extends AbstractAccessDecisionManager {
int deny = 0;
for (AccessDecisionVoter voter : getDecisionVoters()) {
int result = voter.vote(authentication, object, configAttributes);
this.logger.debug(LogMessage.format("Voter: %s, returned: %s", voter, result));
switch (result) {
case AccessDecisionVoter.ACCESS_GRANTED:
return;

View File

@@ -19,7 +19,6 @@ package org.springframework.security.access.vote;
import java.util.Collection;
import java.util.List;
import org.springframework.core.log.LogMessage;
import org.springframework.security.access.AccessDecisionVoter;
import org.springframework.security.access.AccessDeniedException;
import org.springframework.security.access.ConfigAttribute;
@@ -67,7 +66,6 @@ public class ConsensusBased extends AbstractAccessDecisionManager {
int deny = 0;
for (AccessDecisionVoter voter : getDecisionVoters()) {
int result = voter.vote(authentication, object, configAttributes);
this.logger.debug(LogMessage.format("Voter: %s, returned: %s", voter, result));
switch (result) {
case AccessDecisionVoter.ACCESS_GRANTED:
grant++;

View File

@@ -20,7 +20,6 @@ import java.util.ArrayList;
import java.util.Collection;
import java.util.List;
import org.springframework.core.log.LogMessage;
import org.springframework.security.access.AccessDecisionVoter;
import org.springframework.security.access.AccessDeniedException;
import org.springframework.security.access.ConfigAttribute;
@@ -67,7 +66,6 @@ public class UnanimousBased extends AbstractAccessDecisionManager {
singleAttributeList.set(0, attribute);
for (AccessDecisionVoter voter : getDecisionVoters()) {
int result = voter.vote(authentication, object, singleAttributeList);
this.logger.debug(LogMessage.format("Voter: %s, returned: %s", voter, result));
switch (result) {
case AccessDecisionVoter.ACCESS_GRANTED:
grant++;

View File

@@ -174,24 +174,13 @@ public abstract class AbstractAuthenticationToken implements Authentication, Cre
@Override
public String toString() {
StringBuilder sb = new StringBuilder();
sb.append(super.toString()).append(": ");
sb.append("Principal: ").append(this.getPrincipal()).append("; ");
sb.append("Credentials: [PROTECTED]; ");
sb.append("Authenticated: ").append(this.isAuthenticated()).append("; ");
sb.append("Details: ").append(this.getDetails()).append("; ");
if (!this.authorities.isEmpty()) {
sb.append("Granted Authorities: ");
int i = 0;
for (GrantedAuthority authority : this.authorities) {
if (i++ > 0) {
sb.append(", ");
}
sb.append(authority);
}
}
else {
sb.append("Not granted any authorities");
}
sb.append(getClass().getSimpleName()).append(" [");
sb.append("Principal=").append(getPrincipal()).append(", ");
sb.append("Credentials=[PROTECTED], ");
sb.append("Authenticated=").append(isAuthenticated()).append(", ");
sb.append("Details=").append(getDetails()).append(", ");
sb.append("Granted Authorities=").append(this.authorities);
sb.append("]");
return sb.toString();
}

View File

@@ -16,6 +16,9 @@
package org.springframework.security.authentication;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.springframework.context.MessageSource;
import org.springframework.context.MessageSourceAware;
import org.springframework.context.support.MessageSourceAccessor;
@@ -29,23 +32,29 @@ import org.springframework.util.Assert;
*/
public class AccountStatusUserDetailsChecker implements UserDetailsChecker, MessageSourceAware {
private final Log logger = LogFactory.getLog(getClass());
protected MessageSourceAccessor messages = SpringSecurityMessageSource.getAccessor();
@Override
public void check(UserDetails user) {
if (!user.isAccountNonLocked()) {
this.logger.debug("Failed to authenticate since user account is locked");
throw new LockedException(
this.messages.getMessage("AccountStatusUserDetailsChecker.locked", "User account is locked"));
}
if (!user.isEnabled()) {
this.logger.debug("Failed to authenticate since user account is disabled");
throw new DisabledException(
this.messages.getMessage("AccountStatusUserDetailsChecker.disabled", "User is disabled"));
}
if (!user.isAccountNonExpired()) {
this.logger.debug("Failed to authenticate since user account is expired");
throw new AccountExpiredException(
this.messages.getMessage("AccountStatusUserDetailsChecker.expired", "User account has expired"));
}
if (!user.isCredentialsNonExpired()) {
this.logger.debug("Failed to authenticate since user account credentials have expired");
throw new CredentialsExpiredException(this.messages
.getMessage("AccountStatusUserDetailsChecker.credentialsExpired", "User credentials have expired"));
}

View File

@@ -168,11 +168,16 @@ public class ProviderManager implements AuthenticationManager, MessageSourceAwar
AuthenticationException parentException = null;
Authentication result = null;
Authentication parentResult = null;
int currentPosition = 0;
int size = this.providers.size();
for (AuthenticationProvider provider : getProviders()) {
if (!provider.supports(toTest)) {
continue;
}
logger.debug(LogMessage.format("Authentication attempt using %s", provider.getClass().getName()));
if (logger.isTraceEnabled()) {
logger.trace(LogMessage.format("Authenticating request with %s (%d/%d)",
provider.getClass().getSimpleName(), ++currentPosition, size));
}
try {
result = provider.authenticate(authentication);
if (result != null) {
@@ -220,6 +225,7 @@ public class ProviderManager implements AuthenticationManager, MessageSourceAwar
if (parentResult == null) {
this.eventPublisher.publishAuthenticationSuccess(result);
}
return result;
}

View File

@@ -133,7 +133,7 @@ public abstract class AbstractUserDetailsAuthenticationProvider
user = retrieveUser(username, (UsernamePasswordAuthenticationToken) authentication);
}
catch (UsernameNotFoundException ex) {
this.logger.debug("User '" + username + "' not found");
this.logger.debug("Failed to find user '" + username + "'");
if (!this.hideUserNotFoundExceptions) {
throw ex;
}
@@ -196,6 +196,7 @@ public abstract class AbstractUserDetailsAuthenticationProvider
UsernamePasswordAuthenticationToken result = new UsernamePasswordAuthenticationToken(principal,
authentication.getCredentials(), this.authoritiesMapper.mapAuthorities(user.getAuthorities()));
result.setDetails(authentication.getDetails());
this.logger.debug("Authenticated user");
return result;
}
@@ -318,17 +319,20 @@ public abstract class AbstractUserDetailsAuthenticationProvider
@Override
public void check(UserDetails user) {
if (!user.isAccountNonLocked()) {
AbstractUserDetailsAuthenticationProvider.this.logger.debug("User account is locked");
AbstractUserDetailsAuthenticationProvider.this.logger
.debug("Failed to authenticate since user account is locked");
throw new LockedException(AbstractUserDetailsAuthenticationProvider.this.messages
.getMessage("AbstractUserDetailsAuthenticationProvider.locked", "User account is locked"));
}
if (!user.isEnabled()) {
AbstractUserDetailsAuthenticationProvider.this.logger.debug("User account is disabled");
AbstractUserDetailsAuthenticationProvider.this.logger
.debug("Failed to authenticate since user account is disabled");
throw new DisabledException(AbstractUserDetailsAuthenticationProvider.this.messages
.getMessage("AbstractUserDetailsAuthenticationProvider.disabled", "User is disabled"));
}
if (!user.isAccountNonExpired()) {
AbstractUserDetailsAuthenticationProvider.this.logger.debug("User account is expired");
AbstractUserDetailsAuthenticationProvider.this.logger
.debug("Failed to authenticate since user account has expired");
throw new AccountExpiredException(AbstractUserDetailsAuthenticationProvider.this.messages
.getMessage("AbstractUserDetailsAuthenticationProvider.expired", "User account has expired"));
}
@@ -341,7 +345,8 @@ public abstract class AbstractUserDetailsAuthenticationProvider
@Override
public void check(UserDetails user) {
if (!user.isCredentialsNonExpired()) {
AbstractUserDetailsAuthenticationProvider.this.logger.debug("User account credentials have expired");
AbstractUserDetailsAuthenticationProvider.this.logger
.debug("Failed to authenticate since user account credentials have expired");
throw new CredentialsExpiredException(AbstractUserDetailsAuthenticationProvider.this.messages
.getMessage("AbstractUserDetailsAuthenticationProvider.credentialsExpired",
"User credentials have expired"));

View File

@@ -68,13 +68,13 @@ public class DaoAuthenticationProvider extends AbstractUserDetailsAuthentication
protected void additionalAuthenticationChecks(UserDetails userDetails,
UsernamePasswordAuthenticationToken authentication) throws AuthenticationException {
if (authentication.getCredentials() == null) {
this.logger.debug("Authentication failed: no credentials provided");
this.logger.debug("Failed to authenticate since no credentials provided");
throw new BadCredentialsException(this.messages
.getMessage("AbstractUserDetailsAuthenticationProvider.badCredentials", "Bad credentials"));
}
String presentedPassword = authentication.getCredentials().toString();
if (!this.passwordEncoder.matches(presentedPassword, userDetails.getPassword())) {
this.logger.debug("Authentication failed: password does not match stored value");
this.logger.debug("Failed to authenticate since password does not match stored value");
throw new BadCredentialsException(this.messages
.getMessage("AbstractUserDetailsAuthenticationProvider.badCredentials", "Bad credentials"));
}

View File

@@ -73,13 +73,14 @@ public class SecurityContextImpl implements SecurityContext {
@Override
public String toString() {
StringBuilder sb = new StringBuilder();
sb.append(super.toString());
sb.append(getClass().getSimpleName()).append(" [");
if (this.authentication == null) {
sb.append(": Null authentication");
sb.append("Null authentication");
}
else {
sb.append(": Authentication: ").append(this.authentication);
sb.append("Authentication=").append(this.authentication);
}
sb.append("]");
return sb.toString();
}

View File

@@ -196,27 +196,14 @@ public class User implements UserDetails, CredentialsContainer {
@Override
public String toString() {
StringBuilder sb = new StringBuilder();
sb.append(super.toString()).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.authorities.isEmpty()) {
sb.append("Granted Authorities: ");
boolean first = true;
for (GrantedAuthority auth : this.authorities) {
if (!first) {
sb.append(",");
}
first = false;
sb.append(auth);
}
}
else {
sb.append("Not granted any authorities");
}
sb.append(getClass().getName()).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(this.authorities).append("]");
return sb.toString();
}

View File

@@ -68,4 +68,9 @@ public class SimpleMethodInvocation implements MethodInvocation {
throw new UnsupportedOperationException("mock method not implemented");
}
@Override
public String toString() {
return "method invocation [" + this.method + "]";
}
}

View File

@@ -111,7 +111,7 @@ public class AbstractAuthenticationTokenTests {
@Test
public void testToStringWithNullAuthorities() {
MockAuthenticationImpl token = new MockAuthenticationImpl("Test", "Password", null);
assertThat(token.toString().lastIndexOf("Not granted any authorities") != -1).isTrue();
assertThat(token.toString().lastIndexOf("Granted Authorities=[]") != -1).isTrue();
}
@Test