diff --git a/config/src/main/java/org/springframework/security/config/annotation/authentication/configuration/AuthenticationConfiguration.java b/config/src/main/java/org/springframework/security/config/annotation/authentication/configuration/AuthenticationConfiguration.java index 821a88d3d2..fd779ebc95 100644 --- a/config/src/main/java/org/springframework/security/config/annotation/authentication/configuration/AuthenticationConfiguration.java +++ b/config/src/main/java/org/springframework/security/config/annotation/authentication/configuration/AuthenticationConfiguration.java @@ -212,7 +212,9 @@ public class AuthenticationConfiguration { public void init(AuthenticationManagerBuilder auth) { Map beansWithAnnotation = this.context .getBeansWithAnnotation(EnableGlobalAuthentication.class); - logger.debug(LogMessage.format("Eagerly initializing %s", beansWithAnnotation)); + if (logger.isTraceEnabled()) { + logger.trace(LogMessage.format("Eagerly initializing %s", beansWithAnnotation)); + } } } diff --git a/core/src/main/java/org/springframework/security/access/intercept/AbstractSecurityInterceptor.java b/core/src/main/java/org/springframework/security/access/intercept/AbstractSecurityInterceptor.java index d92a5ed500..8b385fbae6 100644 --- a/core/src/main/java/org/springframework/security/access/intercept/AbstractSecurityInterceptor.java +++ b/core/src/main/java/org/springframework/security/access/intercept/AbstractSecurityInterceptor.java @@ -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; } diff --git a/core/src/main/java/org/springframework/security/access/vote/AbstractAccessDecisionManager.java b/core/src/main/java/org/springframework/security/access/vote/AbstractAccessDecisionManager.java index 50d835df37..75b41a54ae 100644 --- a/core/src/main/java/org/springframework/security/access/vote/AbstractAccessDecisionManager.java +++ b/core/src/main/java/org/springframework/security/access/vote/AbstractAccessDecisionManager.java @@ -115,4 +115,10 @@ public abstract class AbstractAccessDecisionManager return true; } + @Override + public String toString() { + return this.getClass().getSimpleName() + " [DecisionVoters=" + this.decisionVoters + + ", AllowIfAllAbstainDecisions=" + this.allowIfAllAbstainDecisions + "]"; + } + } diff --git a/core/src/main/java/org/springframework/security/access/vote/AffirmativeBased.java b/core/src/main/java/org/springframework/security/access/vote/AffirmativeBased.java index 718ed9f15f..86841e1f05 100644 --- a/core/src/main/java/org/springframework/security/access/vote/AffirmativeBased.java +++ b/core/src/main/java/org/springframework/security/access/vote/AffirmativeBased.java @@ -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; diff --git a/core/src/main/java/org/springframework/security/access/vote/ConsensusBased.java b/core/src/main/java/org/springframework/security/access/vote/ConsensusBased.java index 3a98a61a49..4f217e7af8 100644 --- a/core/src/main/java/org/springframework/security/access/vote/ConsensusBased.java +++ b/core/src/main/java/org/springframework/security/access/vote/ConsensusBased.java @@ -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++; diff --git a/core/src/main/java/org/springframework/security/access/vote/UnanimousBased.java b/core/src/main/java/org/springframework/security/access/vote/UnanimousBased.java index edadbb9f49..6bd4b27243 100644 --- a/core/src/main/java/org/springframework/security/access/vote/UnanimousBased.java +++ b/core/src/main/java/org/springframework/security/access/vote/UnanimousBased.java @@ -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++; diff --git a/core/src/main/java/org/springframework/security/authentication/AbstractAuthenticationToken.java b/core/src/main/java/org/springframework/security/authentication/AbstractAuthenticationToken.java index 422ce529d3..78cec88812 100644 --- a/core/src/main/java/org/springframework/security/authentication/AbstractAuthenticationToken.java +++ b/core/src/main/java/org/springframework/security/authentication/AbstractAuthenticationToken.java @@ -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(); } diff --git a/core/src/main/java/org/springframework/security/authentication/AccountStatusUserDetailsChecker.java b/core/src/main/java/org/springframework/security/authentication/AccountStatusUserDetailsChecker.java index 9770a62111..7b7e296ce5 100644 --- a/core/src/main/java/org/springframework/security/authentication/AccountStatusUserDetailsChecker.java +++ b/core/src/main/java/org/springframework/security/authentication/AccountStatusUserDetailsChecker.java @@ -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")); } diff --git a/core/src/main/java/org/springframework/security/authentication/ProviderManager.java b/core/src/main/java/org/springframework/security/authentication/ProviderManager.java index 622c0284b1..bc54e4c026 100644 --- a/core/src/main/java/org/springframework/security/authentication/ProviderManager.java +++ b/core/src/main/java/org/springframework/security/authentication/ProviderManager.java @@ -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; } diff --git a/core/src/main/java/org/springframework/security/authentication/dao/AbstractUserDetailsAuthenticationProvider.java b/core/src/main/java/org/springframework/security/authentication/dao/AbstractUserDetailsAuthenticationProvider.java index 953e99455c..f85306cdd3 100644 --- a/core/src/main/java/org/springframework/security/authentication/dao/AbstractUserDetailsAuthenticationProvider.java +++ b/core/src/main/java/org/springframework/security/authentication/dao/AbstractUserDetailsAuthenticationProvider.java @@ -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")); diff --git a/core/src/main/java/org/springframework/security/authentication/dao/DaoAuthenticationProvider.java b/core/src/main/java/org/springframework/security/authentication/dao/DaoAuthenticationProvider.java index 245101592f..6d65494af1 100644 --- a/core/src/main/java/org/springframework/security/authentication/dao/DaoAuthenticationProvider.java +++ b/core/src/main/java/org/springframework/security/authentication/dao/DaoAuthenticationProvider.java @@ -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")); } diff --git a/core/src/main/java/org/springframework/security/core/context/SecurityContextImpl.java b/core/src/main/java/org/springframework/security/core/context/SecurityContextImpl.java index 19c18abb24..734373df57 100644 --- a/core/src/main/java/org/springframework/security/core/context/SecurityContextImpl.java +++ b/core/src/main/java/org/springframework/security/core/context/SecurityContextImpl.java @@ -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(); } diff --git a/core/src/main/java/org/springframework/security/core/userdetails/User.java b/core/src/main/java/org/springframework/security/core/userdetails/User.java index e716f64bd7..86d57704df 100644 --- a/core/src/main/java/org/springframework/security/core/userdetails/User.java +++ b/core/src/main/java/org/springframework/security/core/userdetails/User.java @@ -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(); } diff --git a/core/src/main/java/org/springframework/security/util/SimpleMethodInvocation.java b/core/src/main/java/org/springframework/security/util/SimpleMethodInvocation.java index 37977d3881..41470b5897 100644 --- a/core/src/main/java/org/springframework/security/util/SimpleMethodInvocation.java +++ b/core/src/main/java/org/springframework/security/util/SimpleMethodInvocation.java @@ -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 + "]"; + } + } diff --git a/core/src/test/java/org/springframework/security/authentication/AbstractAuthenticationTokenTests.java b/core/src/test/java/org/springframework/security/authentication/AbstractAuthenticationTokenTests.java index 90c0f82f4a..7329158a9e 100644 --- a/core/src/test/java/org/springframework/security/authentication/AbstractAuthenticationTokenTests.java +++ b/core/src/test/java/org/springframework/security/authentication/AbstractAuthenticationTokenTests.java @@ -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 diff --git a/web/src/main/java/org/springframework/security/web/DefaultRedirectStrategy.java b/web/src/main/java/org/springframework/security/web/DefaultRedirectStrategy.java index b135699766..61c16a3789 100644 --- a/web/src/main/java/org/springframework/security/web/DefaultRedirectStrategy.java +++ b/web/src/main/java/org/springframework/security/web/DefaultRedirectStrategy.java @@ -53,7 +53,9 @@ public class DefaultRedirectStrategy implements RedirectStrategy { public void sendRedirect(HttpServletRequest request, HttpServletResponse response, String url) throws IOException { String redirectUrl = calculateRedirectUrl(request.getContextPath(), url); redirectUrl = response.encodeRedirectURL(redirectUrl); - this.logger.debug(LogMessage.format("Redirecting to '%s'", redirectUrl)); + if (this.logger.isDebugEnabled()) { + this.logger.debug(LogMessage.format("Redirecting to %s", redirectUrl)); + } response.sendRedirect(redirectUrl); } diff --git a/web/src/main/java/org/springframework/security/web/DefaultSecurityFilterChain.java b/web/src/main/java/org/springframework/security/web/DefaultSecurityFilterChain.java index 6e52979b6e..1961bf84fd 100644 --- a/web/src/main/java/org/springframework/security/web/DefaultSecurityFilterChain.java +++ b/web/src/main/java/org/springframework/security/web/DefaultSecurityFilterChain.java @@ -48,7 +48,7 @@ public final class DefaultSecurityFilterChain implements SecurityFilterChain { } public DefaultSecurityFilterChain(RequestMatcher requestMatcher, List filters) { - logger.info(LogMessage.format("Creating filter chain: %s, %s", requestMatcher, filters)); + logger.info(LogMessage.format("Will secure %s with %s", requestMatcher, filters)); this.requestMatcher = requestMatcher; this.filters = new ArrayList<>(filters); } @@ -69,7 +69,8 @@ public final class DefaultSecurityFilterChain implements SecurityFilterChain { @Override public String toString() { - return "[ " + this.requestMatcher + ", " + this.filters + "]"; + return this.getClass().getSimpleName() + " [RequestMatcher=" + this.requestMatcher + ", Filters=" + this.filters + + "]"; } } diff --git a/web/src/main/java/org/springframework/security/web/FilterChainProxy.java b/web/src/main/java/org/springframework/security/web/FilterChainProxy.java index 6a71c73e26..5b2d439228 100644 --- a/web/src/main/java/org/springframework/security/web/FilterChainProxy.java +++ b/web/src/main/java/org/springframework/security/web/FilterChainProxy.java @@ -197,12 +197,16 @@ public class FilterChainProxy extends GenericFilterBean { HttpServletResponse firewallResponse = this.firewall.getFirewalledResponse((HttpServletResponse) response); List filters = getFilters(firewallRequest); if (filters == null || filters.size() == 0) { - logger.debug(LogMessage.of(() -> UrlUtils.buildRequestUrl(firewallRequest) - + ((filters != null) ? " has an empty filter list" : " has no matching filters"))); + if (logger.isTraceEnabled()) { + logger.trace(LogMessage.of(() -> "No security for " + requestLine(firewallRequest))); + } firewallRequest.reset(); chain.doFilter(firewallRequest, firewallResponse); return; } + if (logger.isDebugEnabled()) { + logger.debug(LogMessage.of(() -> "Securing " + requestLine(firewallRequest))); + } VirtualFilterChain virtualFilterChain = new VirtualFilterChain(firewallRequest, chain, filters); virtualFilterChain.doFilter(firewallRequest, firewallResponse); } @@ -213,7 +217,12 @@ public class FilterChainProxy extends GenericFilterBean { * @return an ordered array of Filters defining the filter chain */ private List getFilters(HttpServletRequest request) { + int count = 0; for (SecurityFilterChain chain : this.filterChains) { + if (logger.isTraceEnabled()) { + logger.trace(LogMessage.format("Trying to match request against %s (%d/%d)", chain, ++count, + this.filterChains.size())); + } if (chain.matches(request)) { return chain.getFilters(); } @@ -279,6 +288,10 @@ public class FilterChainProxy extends GenericFilterBean { return sb.toString(); } + private static String requestLine(HttpServletRequest request) { + return request.getMethod() + " " + UrlUtils.buildRequestUrl(request); + } + /** * Internal {@code FilterChain} implementation that is used to pass a request through * the additional internal list of filters which match the request. @@ -306,8 +319,9 @@ public class FilterChainProxy extends GenericFilterBean { @Override public void doFilter(ServletRequest request, ServletResponse response) throws IOException, ServletException { if (this.currentPosition == this.size) { - logger.debug(LogMessage.of(() -> UrlUtils.buildRequestUrl(this.firewalledRequest) - + " reached end of additional filter chain; proceeding with original chain")); + if (logger.isDebugEnabled()) { + logger.debug(LogMessage.of(() -> "Secured " + requestLine(this.firewalledRequest))); + } // Deactivate path stripping as we exit the security filter chain this.firewalledRequest.reset(); this.originalChain.doFilter(request, response); @@ -315,9 +329,10 @@ public class FilterChainProxy extends GenericFilterBean { } this.currentPosition++; Filter nextFilter = this.additionalFilters.get(this.currentPosition - 1); - logger.debug(LogMessage.of(() -> UrlUtils.buildRequestUrl(this.firewalledRequest) + " at position " - + this.currentPosition + " of " + this.size + " in additional filter chain; firing Filter: '" - + nextFilter.getClass().getSimpleName() + "'")); + if (logger.isTraceEnabled()) { + logger.trace(LogMessage.format("Invoking %s (%d/%d)", nextFilter.getClass().getSimpleName(), + this.currentPosition, this.size)); + } nextFilter.doFilter(request, response, this); } diff --git a/web/src/main/java/org/springframework/security/web/FilterInvocation.java b/web/src/main/java/org/springframework/security/web/FilterInvocation.java index 1062c4eedc..af2c135b6c 100644 --- a/web/src/main/java/org/springframework/security/web/FilterInvocation.java +++ b/web/src/main/java/org/springframework/security/web/FilterInvocation.java @@ -38,6 +38,7 @@ import javax.servlet.http.HttpServletResponse; import org.springframework.http.HttpHeaders; import org.springframework.security.web.util.UrlUtils; import org.springframework.util.Assert; +import org.springframework.util.StringUtils; /** * Holds objects associated with a HTTP filter. @@ -133,7 +134,12 @@ public class FilterInvocation { @Override public String toString() { - return "FilterInvocation: URL: " + getRequestUrl(); + if (StringUtils.isEmpty(this.request.getMethod())) { + return "filter invocation [" + getRequestUrl() + "]"; + } + else { + return "filter invocation [" + this.request.getMethod() + " " + getRequestUrl() + "]"; + } } static class DummyRequest extends HttpServletRequestWrapper { diff --git a/web/src/main/java/org/springframework/security/web/access/AccessDeniedHandlerImpl.java b/web/src/main/java/org/springframework/security/web/access/AccessDeniedHandlerImpl.java index 26315b9ec0..8139d0b2af 100644 --- a/web/src/main/java/org/springframework/security/web/access/AccessDeniedHandlerImpl.java +++ b/web/src/main/java/org/springframework/security/web/access/AccessDeniedHandlerImpl.java @@ -25,6 +25,7 @@ import javax.servlet.http.HttpServletResponse; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; +import org.springframework.core.log.LogMessage; import org.springframework.http.HttpStatus; import org.springframework.security.access.AccessDeniedException; import org.springframework.security.web.WebAttributes; @@ -53,9 +54,11 @@ public class AccessDeniedHandlerImpl implements AccessDeniedHandler { public void handle(HttpServletRequest request, HttpServletResponse response, AccessDeniedException accessDeniedException) throws IOException, ServletException { if (response.isCommitted()) { + logger.trace("Did not write to response since already committed"); return; } if (this.errorPage == null) { + logger.debug("Responding with 403 status code"); response.sendError(HttpStatus.FORBIDDEN.value(), HttpStatus.FORBIDDEN.getReasonPhrase()); return; } @@ -64,6 +67,9 @@ public class AccessDeniedHandlerImpl implements AccessDeniedHandler { // Set the 403 status code. response.setStatus(HttpStatus.FORBIDDEN.value()); // forward to error page. + if (logger.isDebugEnabled()) { + logger.debug(LogMessage.format("Forwarding to %s with status code 403", this.errorPage)); + } request.getRequestDispatcher(this.errorPage).forward(request, response); } diff --git a/web/src/main/java/org/springframework/security/web/access/ExceptionTranslationFilter.java b/web/src/main/java/org/springframework/security/web/access/ExceptionTranslationFilter.java index dd0360aa87..ae7a0367b4 100644 --- a/web/src/main/java/org/springframework/security/web/access/ExceptionTranslationFilter.java +++ b/web/src/main/java/org/springframework/security/web/access/ExceptionTranslationFilter.java @@ -117,7 +117,6 @@ public class ExceptionTranslationFilter extends GenericFilterBean { throws IOException, ServletException { try { chain.doFilter(request, response); - this.logger.debug("Chain processed normally"); } catch (IOException ex) { throw ex; @@ -175,7 +174,7 @@ public class ExceptionTranslationFilter extends GenericFilterBean { private void handleAuthenticationException(HttpServletRequest request, HttpServletResponse response, FilterChain chain, AuthenticationException exception) throws ServletException, IOException { - this.logger.debug("Authentication exception occurred; redirecting to authentication entry point", exception); + this.logger.trace("Sending to authentication entry point since authentication failed", exception); sendStartAuthentication(request, response, chain, exception); } @@ -184,17 +183,21 @@ public class ExceptionTranslationFilter extends GenericFilterBean { Authentication authentication = SecurityContextHolder.getContext().getAuthentication(); boolean isAnonymous = this.authenticationTrustResolver.isAnonymous(authentication); if (isAnonymous || this.authenticationTrustResolver.isRememberMe(authentication)) { - this.logger.debug(LogMessage - .of(() -> "Access is denied (user is " + (isAnonymous ? "anonymous" : "not fully authenticated") - + "); redirecting to authentication entry point"), - exception); + if (logger.isTraceEnabled()) { + logger.trace(LogMessage.format("Sending %s to authentication entry point since access is denied", + authentication), exception); + } sendStartAuthentication(request, response, chain, new InsufficientAuthenticationException( this.messages.getMessage("ExceptionTranslationFilter.insufficientAuthentication", "Full authentication is required to access this resource"))); } else { - this.logger.debug("Access is denied (user is not anonymous); delegating to AccessDeniedHandler", exception); + if (logger.isTraceEnabled()) { + logger.trace( + LogMessage.format("Sending %s to access denied handler since access is denied", authentication), + exception); + } this.accessDeniedHandler.handle(request, response, exception); } } @@ -205,7 +208,6 @@ public class ExceptionTranslationFilter extends GenericFilterBean { // existing Authentication is no longer considered valid SecurityContextHolder.getContext().setAuthentication(null); this.requestCache.saveRequest(request, response); - this.logger.debug("Calling Authentication entry point."); this.authenticationEntryPoint.commence(request, response, reason); } diff --git a/web/src/main/java/org/springframework/security/web/access/expression/ExpressionBasedFilterInvocationSecurityMetadataSource.java b/web/src/main/java/org/springframework/security/web/access/expression/ExpressionBasedFilterInvocationSecurityMetadataSource.java index c1b50f2140..840a4a0b43 100644 --- a/web/src/main/java/org/springframework/security/web/access/expression/ExpressionBasedFilterInvocationSecurityMetadataSource.java +++ b/web/src/main/java/org/springframework/security/web/access/expression/ExpressionBasedFilterInvocationSecurityMetadataSource.java @@ -27,6 +27,7 @@ import javax.servlet.http.HttpServletRequest; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; +import org.springframework.core.log.LogMessage; import org.springframework.expression.ExpressionParser; import org.springframework.expression.ParseException; import org.springframework.security.access.ConfigAttribute; @@ -67,7 +68,9 @@ public final class ExpressionBasedFilterInvocationSecurityMetadataSource private static void process(ExpressionParser parser, RequestMatcher request, Collection value, BiConsumer> consumer) { String expression = getExpression(request, value); - logger.debug("Adding web access control expression '" + expression + "', for " + request); + if (logger.isDebugEnabled()) { + logger.debug(LogMessage.format("Adding web access control expression [%s] for %s", expression, request)); + } AbstractVariableEvaluationContextPostProcessor postProcessor = createPostProcessor(request); ArrayList processed = new ArrayList<>(1); try { diff --git a/web/src/main/java/org/springframework/security/web/access/expression/WebExpressionVoter.java b/web/src/main/java/org/springframework/security/web/access/expression/WebExpressionVoter.java index 0822cb1532..577a0a3263 100644 --- a/web/src/main/java/org/springframework/security/web/access/expression/WebExpressionVoter.java +++ b/web/src/main/java/org/springframework/security/web/access/expression/WebExpressionVoter.java @@ -18,6 +18,9 @@ package org.springframework.security.web.access.expression; import java.util.Collection; +import org.apache.commons.logging.Log; +import org.apache.commons.logging.LogFactory; + import org.springframework.expression.EvaluationContext; import org.springframework.security.access.AccessDecisionVoter; import org.springframework.security.access.ConfigAttribute; @@ -35,6 +38,8 @@ import org.springframework.util.Assert; */ public class WebExpressionVoter implements AccessDecisionVoter { + private final Log logger = LogFactory.getLog(getClass()); + private SecurityExpressionHandler expressionHandler = new DefaultWebSecurityExpressionHandler(); @Override @@ -45,12 +50,18 @@ public class WebExpressionVoter implements AccessDecisionVoter Assert.notNull(attributes, "attributes must not be null"); WebExpressionConfigAttribute webExpressionConfigAttribute = findConfigAttribute(attributes); if (webExpressionConfigAttribute == null) { + this.logger + .trace("Abstained since did not find a config attribute of instance WebExpressionConfigAttribute"); return ACCESS_ABSTAIN; } EvaluationContext ctx = webExpressionConfigAttribute.postProcess( this.expressionHandler.createEvaluationContext(authentication, filterInvocation), filterInvocation); - return ExpressionUtils.evaluateAsBoolean(webExpressionConfigAttribute.getAuthorizeExpression(), ctx) - ? ACCESS_GRANTED : ACCESS_DENIED; + boolean granted = ExpressionUtils.evaluateAsBoolean(webExpressionConfigAttribute.getAuthorizeExpression(), ctx); + if (granted) { + return ACCESS_GRANTED; + } + this.logger.trace("Voted to deny authorization"); + return ACCESS_DENIED; } private WebExpressionConfigAttribute findConfigAttribute(Collection attributes) { diff --git a/web/src/main/java/org/springframework/security/web/access/intercept/DefaultFilterInvocationSecurityMetadataSource.java b/web/src/main/java/org/springframework/security/web/access/intercept/DefaultFilterInvocationSecurityMetadataSource.java index 5f2661a32f..06ac758497 100644 --- a/web/src/main/java/org/springframework/security/web/access/intercept/DefaultFilterInvocationSecurityMetadataSource.java +++ b/web/src/main/java/org/springframework/security/web/access/intercept/DefaultFilterInvocationSecurityMetadataSource.java @@ -27,6 +27,7 @@ import javax.servlet.http.HttpServletRequest; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; +import org.springframework.core.log.LogMessage; import org.springframework.security.access.ConfigAttribute; import org.springframework.security.web.FilterInvocation; import org.springframework.security.web.util.matcher.RequestMatcher; @@ -78,10 +79,17 @@ public class DefaultFilterInvocationSecurityMetadataSource implements FilterInvo @Override public Collection getAttributes(Object object) { final HttpServletRequest request = ((FilterInvocation) object).getRequest(); + int count = 0; for (Map.Entry> entry : this.requestMap.entrySet()) { if (entry.getKey().matches(request)) { return entry.getValue(); } + else { + if (this.logger.isTraceEnabled()) { + this.logger.trace(LogMessage.format("Did not match request to %s - %s (%d/%d)", entry.getKey(), + entry.getValue(), ++count, this.requestMap.size())); + } + } } return null; } diff --git a/web/src/main/java/org/springframework/security/web/authentication/AbstractAuthenticationProcessingFilter.java b/web/src/main/java/org/springframework/security/web/authentication/AbstractAuthenticationProcessingFilter.java index f4f135979f..6da3e7c13c 100644 --- a/web/src/main/java/org/springframework/security/web/authentication/AbstractAuthenticationProcessingFilter.java +++ b/web/src/main/java/org/springframework/security/web/authentication/AbstractAuthenticationProcessingFilter.java @@ -218,7 +218,6 @@ public abstract class AbstractAuthenticationProcessingFilter extends GenericFilt chain.doFilter(request, response); return; } - this.logger.debug("Request is to process authentication"); try { Authentication authenticationResult = attemptAuthentication(request, response); if (authenticationResult == null) { @@ -255,7 +254,14 @@ public abstract class AbstractAuthenticationProcessingFilter extends GenericFilt * false otherwise. */ protected boolean requiresAuthentication(HttpServletRequest request, HttpServletResponse response) { - return this.requiresAuthenticationRequestMatcher.matches(request); + if (this.requiresAuthenticationRequestMatcher.matches(request)) { + return true; + } + if (this.logger.isTraceEnabled()) { + this.logger + .trace(LogMessage.format("Did not match request to %s", this.requiresAuthenticationRequestMatcher)); + } + return false; } /** @@ -304,9 +310,10 @@ public abstract class AbstractAuthenticationProcessingFilter extends GenericFilt */ protected void successfulAuthentication(HttpServletRequest request, HttpServletResponse response, FilterChain chain, Authentication authResult) throws IOException, ServletException { - this.logger.debug( - LogMessage.format("Authentication success. Updating SecurityContextHolder to contain: %s", authResult)); SecurityContextHolder.getContext().setAuthentication(authResult); + if (this.logger.isDebugEnabled()) { + this.logger.debug(LogMessage.format("Set SecurityContextHolder to %s", authResult)); + } this.rememberMeServices.loginSuccess(request, response, authResult); if (this.eventPublisher != null) { this.eventPublisher.publishEvent(new InteractiveAuthenticationSuccessEvent(authResult, this.getClass())); @@ -328,11 +335,9 @@ public abstract class AbstractAuthenticationProcessingFilter extends GenericFilt protected void unsuccessfulAuthentication(HttpServletRequest request, HttpServletResponse response, AuthenticationException failed) throws IOException, ServletException { SecurityContextHolder.clearContext(); - if (this.logger.isDebugEnabled()) { - this.logger.debug("Authentication request failed: " + failed.toString(), failed); - this.logger.debug("Updated SecurityContextHolder to contain null Authentication"); - this.logger.debug("Delegating to authentication failure handler " + this.failureHandler); - } + this.logger.trace("Failed to process authentication request", failed); + this.logger.trace("Cleared SecurityContextHolder"); + this.logger.trace("Handling authentication failure"); this.rememberMeServices.loginFail(request, response); this.failureHandler.onAuthenticationFailure(request, response, failed); } diff --git a/web/src/main/java/org/springframework/security/web/authentication/AbstractAuthenticationTargetUrlRequestHandler.java b/web/src/main/java/org/springframework/security/web/authentication/AbstractAuthenticationTargetUrlRequestHandler.java index f52b0a2a96..1e10dbd232 100644 --- a/web/src/main/java/org/springframework/security/web/authentication/AbstractAuthenticationTargetUrlRequestHandler.java +++ b/web/src/main/java/org/springframework/security/web/authentication/AbstractAuthenticationTargetUrlRequestHandler.java @@ -86,8 +86,7 @@ public abstract class AbstractAuthenticationTargetUrlRequestHandler { throws IOException, ServletException { String targetUrl = determineTargetUrl(request, response, authentication); if (response.isCommitted()) { - this.logger.debug( - LogMessage.format("Response has already been committed. Unable to redirect to %s", targetUrl)); + this.logger.debug(LogMessage.format("Did not redirect to %s since response already committed.", targetUrl)); return; } this.redirectStrategy.sendRedirect(request, response, targetUrl); @@ -114,17 +113,24 @@ public abstract class AbstractAuthenticationTargetUrlRequestHandler { if (this.targetUrlParameter != null) { targetUrl = request.getParameter(this.targetUrlParameter); if (StringUtils.hasText(targetUrl)) { - this.logger.debug("Found targetUrlParameter in request: " + targetUrl); + if (this.logger.isTraceEnabled()) { + this.logger.trace(LogMessage.format("Using url %s from request parameter %s", targetUrl, + this.targetUrlParameter)); + } return targetUrl; } } if (this.useReferer && !StringUtils.hasLength(targetUrl)) { targetUrl = request.getHeader("Referer"); - this.logger.debug("Using Referer header: " + targetUrl); + if (this.logger.isTraceEnabled()) { + this.logger.trace(LogMessage.format("Using url %s from Referer header", targetUrl)); + } } if (!StringUtils.hasText(targetUrl)) { targetUrl = this.defaultTargetUrl; - this.logger.debug("Using default Url: " + targetUrl); + if (this.logger.isTraceEnabled()) { + this.logger.trace(LogMessage.format("Using default url %s", targetUrl)); + } } return targetUrl; } diff --git a/web/src/main/java/org/springframework/security/web/authentication/AnonymousAuthenticationFilter.java b/web/src/main/java/org/springframework/security/web/authentication/AnonymousAuthenticationFilter.java index 1b29bebbe2..0a893b9748 100644 --- a/web/src/main/java/org/springframework/security/web/authentication/AnonymousAuthenticationFilter.java +++ b/web/src/main/java/org/springframework/security/web/authentication/AnonymousAuthenticationFilter.java @@ -88,13 +88,19 @@ public class AnonymousAuthenticationFilter extends GenericFilterBean implements throws IOException, ServletException { if (SecurityContextHolder.getContext().getAuthentication() == null) { SecurityContextHolder.getContext().setAuthentication(createAuthentication((HttpServletRequest) req)); - this.logger.debug(LogMessage.of(() -> "Populated SecurityContextHolder with anonymous token: '" - + SecurityContextHolder.getContext().getAuthentication() + "'")); + if (this.logger.isTraceEnabled()) { + this.logger.trace(LogMessage.of(() -> "Set SecurityContextHolder to " + + SecurityContextHolder.getContext().getAuthentication())); + } + else { + this.logger.debug("Set SecurityContextHolder to anonymous SecurityContext"); + } } else { - this.logger.debug(LogMessage - .of(() -> "SecurityContextHolder not populated with anonymous token, as it already contained: '" - + SecurityContextHolder.getContext().getAuthentication() + "'")); + if (this.logger.isTraceEnabled()) { + this.logger.trace(LogMessage.of(() -> "Did not set SecurityContextHolder since already authenticated " + + SecurityContextHolder.getContext().getAuthentication())); + } } chain.doFilter(req, res); } diff --git a/web/src/main/java/org/springframework/security/web/authentication/AuthenticationFilter.java b/web/src/main/java/org/springframework/security/web/authentication/AuthenticationFilter.java index 89cb9cc5d9..1239336bb9 100644 --- a/web/src/main/java/org/springframework/security/web/authentication/AuthenticationFilter.java +++ b/web/src/main/java/org/springframework/security/web/authentication/AuthenticationFilter.java @@ -138,6 +138,9 @@ public class AuthenticationFilter extends OncePerRequestFilter { protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException { if (!this.requestMatcher.matches(request)) { + if (logger.isTraceEnabled()) { + logger.trace("Did not match request to " + this.requestMatcher); + } filterChain.doFilter(request, response); return; } diff --git a/web/src/main/java/org/springframework/security/web/authentication/SavedRequestAwareAuthenticationSuccessHandler.java b/web/src/main/java/org/springframework/security/web/authentication/SavedRequestAwareAuthenticationSuccessHandler.java index 3fa3802948..9118b86e90 100644 --- a/web/src/main/java/org/springframework/security/web/authentication/SavedRequestAwareAuthenticationSuccessHandler.java +++ b/web/src/main/java/org/springframework/security/web/authentication/SavedRequestAwareAuthenticationSuccessHandler.java @@ -88,7 +88,6 @@ public class SavedRequestAwareAuthenticationSuccessHandler extends SimpleUrlAuth clearAuthenticationAttributes(request); // Use the DefaultSavedRequest URL String targetUrl = savedRequest.getRedirectUrl(); - this.logger.debug("Redirecting to DefaultSavedRequest Url: " + targetUrl); getRedirectStrategy().sendRedirect(request, response, targetUrl); } diff --git a/web/src/main/java/org/springframework/security/web/authentication/SimpleUrlAuthenticationFailureHandler.java b/web/src/main/java/org/springframework/security/web/authentication/SimpleUrlAuthenticationFailureHandler.java index 8eba0ffa1d..96e327d22c 100644 --- a/web/src/main/java/org/springframework/security/web/authentication/SimpleUrlAuthenticationFailureHandler.java +++ b/web/src/main/java/org/springframework/security/web/authentication/SimpleUrlAuthenticationFailureHandler.java @@ -77,7 +77,12 @@ public class SimpleUrlAuthenticationFailureHandler implements AuthenticationFail public void onAuthenticationFailure(HttpServletRequest request, HttpServletResponse response, AuthenticationException exception) throws IOException, ServletException { if (this.defaultFailureUrl == null) { - this.logger.debug("No failure URL set, sending 401 Unauthorized error"); + if (this.logger.isTraceEnabled()) { + this.logger.trace("Sending 401 Unauthorized error since no failure URL is set"); + } + else { + this.logger.debug("Sending 401 Unauthorized error"); + } response.sendError(HttpStatus.UNAUTHORIZED.value(), HttpStatus.UNAUTHORIZED.getReasonPhrase()); return; } @@ -87,7 +92,6 @@ public class SimpleUrlAuthenticationFailureHandler implements AuthenticationFail request.getRequestDispatcher(this.defaultFailureUrl).forward(request, response); } else { - this.logger.debug("Redirecting to " + this.defaultFailureUrl); this.redirectStrategy.sendRedirect(request, response, this.defaultFailureUrl); } } diff --git a/web/src/main/java/org/springframework/security/web/authentication/WebAuthenticationDetails.java b/web/src/main/java/org/springframework/security/web/authentication/WebAuthenticationDetails.java index 41052b4fb9..34586abd46 100644 --- a/web/src/main/java/org/springframework/security/web/authentication/WebAuthenticationDetails.java +++ b/web/src/main/java/org/springframework/security/web/authentication/WebAuthenticationDetails.java @@ -121,9 +121,9 @@ public class WebAuthenticationDetails implements Serializable { @Override public String toString() { StringBuilder sb = new StringBuilder(); - sb.append(super.toString()).append(": "); - sb.append("RemoteIpAddress: ").append(this.getRemoteAddress()).append("; "); - sb.append("SessionId: ").append(this.getSessionId()); + sb.append(getClass().getSimpleName()).append(" ["); + sb.append("RemoteIpAddress=").append(this.getRemoteAddress()).append(", "); + sb.append("SessionId=").append(this.getSessionId()).append("]"); return sb.toString(); } diff --git a/web/src/main/java/org/springframework/security/web/authentication/logout/LogoutFilter.java b/web/src/main/java/org/springframework/security/web/authentication/logout/LogoutFilter.java index 54ec8ee6bb..0c70eb0eb9 100644 --- a/web/src/main/java/org/springframework/security/web/authentication/logout/LogoutFilter.java +++ b/web/src/main/java/org/springframework/security/web/authentication/logout/LogoutFilter.java @@ -93,7 +93,9 @@ public class LogoutFilter extends GenericFilterBean { throws IOException, ServletException { if (requiresLogout(request, response)) { Authentication auth = SecurityContextHolder.getContext().getAuthentication(); - this.logger.debug(LogMessage.format("Logging out user '%s' and transferring to logout destination", auth)); + if (this.logger.isDebugEnabled()) { + this.logger.debug(LogMessage.format("Logging out [%s]", auth)); + } this.handler.logout(request, response, auth); this.logoutSuccessHandler.onLogoutSuccess(request, response, auth); return; @@ -108,7 +110,13 @@ public class LogoutFilter extends GenericFilterBean { * @return true if logout should occur, false otherwise */ protected boolean requiresLogout(HttpServletRequest request, HttpServletResponse response) { - return this.logoutRequestMatcher.matches(request); + if (this.logoutRequestMatcher.matches(request)) { + return true; + } + if (this.logger.isTraceEnabled()) { + this.logger.trace(LogMessage.format("Did not match request to %s", this.logoutRequestMatcher)); + } + return false; } public void setLogoutRequestMatcher(RequestMatcher logoutRequestMatcher) { diff --git a/web/src/main/java/org/springframework/security/web/authentication/logout/SecurityContextLogoutHandler.java b/web/src/main/java/org/springframework/security/web/authentication/logout/SecurityContextLogoutHandler.java index 76c5104553..97b1156691 100644 --- a/web/src/main/java/org/springframework/security/web/authentication/logout/SecurityContextLogoutHandler.java +++ b/web/src/main/java/org/springframework/security/web/authentication/logout/SecurityContextLogoutHandler.java @@ -62,8 +62,10 @@ public class SecurityContextLogoutHandler implements LogoutHandler { if (this.invalidateHttpSession) { HttpSession session = request.getSession(false); if (session != null) { - this.logger.debug(LogMessage.format("Invalidating session: %s", session.getId())); session.invalidate(); + if (this.logger.isDebugEnabled()) { + this.logger.debug(LogMessage.format("Invalidated session %s", session.getId())); + } } } if (this.clearAuthentication) { diff --git a/web/src/main/java/org/springframework/security/web/authentication/preauth/AbstractPreAuthenticatedProcessingFilter.java b/web/src/main/java/org/springframework/security/web/authentication/preauth/AbstractPreAuthenticatedProcessingFilter.java index b31cd91473..6ee3d98e51 100755 --- a/web/src/main/java/org/springframework/security/web/authentication/preauth/AbstractPreAuthenticatedProcessingFilter.java +++ b/web/src/main/java/org/springframework/security/web/authentication/preauth/AbstractPreAuthenticatedProcessingFilter.java @@ -125,11 +125,19 @@ public abstract class AbstractPreAuthenticatedProcessingFilter extends GenericFi @Override public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException { - this.logger.debug(LogMessage - .of(() -> "Checking secure context token: " + SecurityContextHolder.getContext().getAuthentication())); if (this.requiresAuthenticationRequestMatcher.matches((HttpServletRequest) request)) { + if (logger.isDebugEnabled()) { + logger.debug(LogMessage + .of(() -> "Authenticating " + SecurityContextHolder.getContext().getAuthentication())); + } doAuthenticate((HttpServletRequest) request, (HttpServletResponse) response); } + else { + if (logger.isTraceEnabled()) { + logger.trace(LogMessage.format("Did not authenticate since request did not match [%s]", + this.requiresAuthenticationRequestMatcher)); + } + } chain.doFilter(request, response); } diff --git a/web/src/main/java/org/springframework/security/web/authentication/session/AbstractSessionFixationProtectionStrategy.java b/web/src/main/java/org/springframework/security/web/authentication/session/AbstractSessionFixationProtectionStrategy.java index c4f497bf1b..3f7183b5a7 100644 --- a/web/src/main/java/org/springframework/security/web/authentication/session/AbstractSessionFixationProtectionStrategy.java +++ b/web/src/main/java/org/springframework/security/web/authentication/session/AbstractSessionFixationProtectionStrategy.java @@ -26,6 +26,7 @@ import org.apache.commons.logging.LogFactory; import org.springframework.context.ApplicationEvent; import org.springframework.context.ApplicationEventPublisher; import org.springframework.context.ApplicationEventPublisherAware; +import org.springframework.core.log.LogMessage; import org.springframework.security.core.Authentication; import org.springframework.util.Assert; import org.springframework.web.util.WebUtils; @@ -93,6 +94,11 @@ public abstract class AbstractSessionFixationProtectionStrategy this.logger.warn("Your servlet container did not change the session ID when a new session " + "was created. You will not be adequately protected against session-fixation attacks"); } + else { + if (this.logger.isDebugEnabled()) { + this.logger.debug(LogMessage.format("Changed session id from %s", originalSessionId)); + } + } onSessionChange(originalSessionId, session, authentication); } } diff --git a/web/src/main/java/org/springframework/security/web/authentication/session/CompositeSessionAuthenticationStrategy.java b/web/src/main/java/org/springframework/security/web/authentication/session/CompositeSessionAuthenticationStrategy.java index b1e53ec772..7473201df8 100644 --- a/web/src/main/java/org/springframework/security/web/authentication/session/CompositeSessionAuthenticationStrategy.java +++ b/web/src/main/java/org/springframework/security/web/authentication/session/CompositeSessionAuthenticationStrategy.java @@ -72,8 +72,13 @@ public class CompositeSessionAuthenticationStrategy implements SessionAuthentica @Override public void onAuthentication(Authentication authentication, HttpServletRequest request, HttpServletResponse response) throws SessionAuthenticationException { + int currentPosition = 0; + int size = this.delegateStrategies.size(); for (SessionAuthenticationStrategy delegate : this.delegateStrategies) { - this.logger.debug(LogMessage.format("Delegating to %s", delegate)); + if (this.logger.isTraceEnabled()) { + this.logger.trace(LogMessage.format("Preparing session with %s (%d/%d)", + delegate.getClass().getSimpleName(), ++currentPosition, size)); + } delegate.onAuthentication(authentication, request, response); } } diff --git a/web/src/main/java/org/springframework/security/web/authentication/switchuser/SwitchUserFilter.java b/web/src/main/java/org/springframework/security/web/authentication/switchuser/SwitchUserFilter.java index 6fff566ed7..11e1ed94ba 100644 --- a/web/src/main/java/org/springframework/security/web/authentication/switchuser/SwitchUserFilter.java +++ b/web/src/main/java/org/springframework/security/web/authentication/switchuser/SwitchUserFilter.java @@ -179,7 +179,7 @@ public class SwitchUserFilter extends GenericFilterBean implements ApplicationEv this.successHandler.onAuthenticationSuccess(request, response, targetUser); } catch (AuthenticationException ex) { - this.logger.debug("Switch User failed", ex); + this.logger.debug("Failed to switch user", ex); this.failureHandler.onAuthenticationFailure(request, response, ex); } return; diff --git a/web/src/main/java/org/springframework/security/web/authentication/ui/DefaultLogoutPageGeneratingFilter.java b/web/src/main/java/org/springframework/security/web/authentication/ui/DefaultLogoutPageGeneratingFilter.java index 84f6cde296..22811d01cf 100644 --- a/web/src/main/java/org/springframework/security/web/authentication/ui/DefaultLogoutPageGeneratingFilter.java +++ b/web/src/main/java/org/springframework/security/web/authentication/ui/DefaultLogoutPageGeneratingFilter.java @@ -26,6 +26,7 @@ import javax.servlet.ServletException; import javax.servlet.http.HttpServletRequest; import javax.servlet.http.HttpServletResponse; +import org.springframework.core.log.LogMessage; import org.springframework.security.web.util.matcher.AntPathRequestMatcher; import org.springframework.security.web.util.matcher.RequestMatcher; import org.springframework.util.Assert; @@ -50,6 +51,10 @@ public class DefaultLogoutPageGeneratingFilter extends OncePerRequestFilter { renderLogout(request, response); } else { + if (logger.isTraceEnabled()) { + logger.trace(LogMessage.format("Did not render default logout page since request did not match [%s]", + this.matcher)); + } filterChain.doFilter(request, response); } } diff --git a/web/src/main/java/org/springframework/security/web/context/HttpSessionSecurityContextRepository.java b/web/src/main/java/org/springframework/security/web/context/HttpSessionSecurityContextRepository.java index e58ad9ef6b..be42b9a89c 100644 --- a/web/src/main/java/org/springframework/security/web/context/HttpSessionSecurityContextRepository.java +++ b/web/src/main/java/org/springframework/security/web/context/HttpSessionSecurityContextRepository.java @@ -118,11 +118,10 @@ public class HttpSessionSecurityContextRepository implements SecurityContextRepo HttpSession httpSession = request.getSession(false); SecurityContext context = readSecurityContextFromSession(httpSession); if (context == null) { - this.logger.debug(LogMessage.format( - "No SecurityContext was available from the HttpSession: %s. A new one will be created.", - httpSession)); context = generateNewContext(); - + if (this.logger.isTraceEnabled()) { + this.logger.trace(LogMessage.format("Created %s", context)); + } } SaveToSessionResponseWrapper wrappedResponse = new SaveToSessionResponseWrapper(response, request, httpSession != null, context); @@ -159,13 +158,16 @@ public class HttpSessionSecurityContextRepository implements SecurityContextRepo */ private SecurityContext readSecurityContextFromSession(HttpSession httpSession) { if (httpSession == null) { - this.logger.debug("No HttpSession currently exists"); + this.logger.trace("No HttpSession currently exists"); return null; } // Session exists, so try to obtain a context from it. Object contextFromSession = httpSession.getAttribute(this.springSecurityContextKey); if (contextFromSession == null) { - this.logger.debug("HttpSession returned null object for SPRING_SECURITY_CONTEXT"); + if (this.logger.isTraceEnabled()) { + this.logger.trace(LogMessage.format("Did not find SecurityContext in HttpSession %s " + + "using the SPRING_SECURITY_CONTEXT session attribute", httpSession.getId())); + } return null; } @@ -179,8 +181,13 @@ public class HttpSessionSecurityContextRepository implements SecurityContextRepo return null; } - this.logger.debug(LogMessage.format("Obtained a valid SecurityContext from %s: '%s'", - this.springSecurityContextKey, contextFromSession)); + if (this.logger.isTraceEnabled()) { + this.logger.trace( + LogMessage.format("Retrieved %s from %s", contextFromSession, this.springSecurityContextKey)); + } + else if (this.logger.isDebugEnabled()) { + this.logger.debug(LogMessage.format("Retrieved %s", contextFromSession)); + } // Everything OK. The only non-null return from this method. return (SecurityContext) contextFromSession; } @@ -328,13 +335,19 @@ public class HttpSessionSecurityContextRepository implements SecurityContextRepo // See SEC-776 if (authentication == null || HttpSessionSecurityContextRepository.this.trustResolver.isAnonymous(authentication)) { - this.logger.debug("SecurityContext is empty or contents are anonymous - " - + "context will not be stored in HttpSession."); if (httpSession != null && this.authBeforeExecution != null) { // SEC-1587 A non-anonymous context may still be in the session // SEC-1735 remove if the contextBeforeExecution was not anonymous httpSession.removeAttribute(springSecurityContextKey); } + if (this.logger.isDebugEnabled()) { + if (authentication == null) { + this.logger.debug("Did not store empty SecurityContext"); + } + else { + this.logger.debug("Did not store anonymous SecurityContext"); + } + } return; } httpSession = (httpSession != null) ? httpSession : createNewSessionIfAllowed(context); @@ -345,8 +358,9 @@ public class HttpSessionSecurityContextRepository implements SecurityContextRepo // is set SEC-1561 if (contextChanged(context) || httpSession.getAttribute(springSecurityContextKey) == null) { httpSession.setAttribute(springSecurityContextKey, context); - this.logger.debug(LogMessage.format("SecurityContext '%s' stored to HttpSession: '%s'", context, - httpSession)); + if (this.logger.isDebugEnabled()) { + this.logger.debug(LogMessage.format("Stored %s to HttpSession [%s]", context, httpSession)); + } } } } @@ -376,13 +390,14 @@ public class HttpSessionSecurityContextRepository implements SecurityContextRepo if (HttpSessionSecurityContextRepository.this.contextObject.equals(context)) { this.logger.debug(LogMessage.format( "HttpSession is null, but SecurityContext has not changed from " - + "default empty context: '%s'; not creating HttpSession or storing SecurityContext", + + "default empty context %s so not creating HttpSession or storing SecurityContext", context)); return null; } - this.logger.debug("HttpSession being created as SecurityContext is non-default"); try { - return this.request.getSession(true); + HttpSession session = this.request.getSession(true); + this.logger.debug("Created HttpSession as SecurityContext is non-default"); + return session; } catch (IllegalStateException ex) { // Response must already be committed, therefore can't create a new diff --git a/web/src/main/java/org/springframework/security/web/context/SecurityContextPersistenceFilter.java b/web/src/main/java/org/springframework/security/web/context/SecurityContextPersistenceFilter.java index 0077c71d46..9a369a2161 100644 --- a/web/src/main/java/org/springframework/security/web/context/SecurityContextPersistenceFilter.java +++ b/web/src/main/java/org/springframework/security/web/context/SecurityContextPersistenceFilter.java @@ -90,12 +90,23 @@ public class SecurityContextPersistenceFilter extends GenericFilterBean { request.setAttribute(FILTER_APPLIED, Boolean.TRUE); if (this.forceEagerSessionCreation) { HttpSession session = request.getSession(); - this.logger.debug(LogMessage.format("Eagerly created session: %s", session.getId())); + if (this.logger.isDebugEnabled() && session.isNew()) { + this.logger.debug(LogMessage.format("Created session %s eagerly", session.getId())); + } } HttpRequestResponseHolder holder = new HttpRequestResponseHolder(request, response); SecurityContext contextBeforeChainExecution = this.repo.loadContext(holder); try { SecurityContextHolder.setContext(contextBeforeChainExecution); + if (contextBeforeChainExecution.getAuthentication() == null) { + logger.debug("Set SecurityContextHolder to empty SecurityContext"); + } + else { + if (this.logger.isDebugEnabled()) { + this.logger + .debug(LogMessage.format("Set SecurityContextHolder to %s", contextBeforeChainExecution)); + } + } chain.doFilter(holder.getRequest(), holder.getResponse()); } finally { @@ -104,7 +115,7 @@ public class SecurityContextPersistenceFilter extends GenericFilterBean { SecurityContextHolder.clearContext(); this.repo.saveContext(contextAfterChainExecution, holder.getRequest(), holder.getResponse()); request.removeAttribute(FILTER_APPLIED); - this.logger.debug("SecurityContextHolder now cleared, as request processing completed"); + this.logger.debug("Cleared SecurityContextHolder to complete request"); } } diff --git a/web/src/main/java/org/springframework/security/web/csrf/CsrfAuthenticationStrategy.java b/web/src/main/java/org/springframework/security/web/csrf/CsrfAuthenticationStrategy.java index 54de46b586..f6a19a266d 100644 --- a/web/src/main/java/org/springframework/security/web/csrf/CsrfAuthenticationStrategy.java +++ b/web/src/main/java/org/springframework/security/web/csrf/CsrfAuthenticationStrategy.java @@ -19,6 +19,9 @@ package org.springframework.security.web.csrf; import javax.servlet.http.HttpServletRequest; import javax.servlet.http.HttpServletResponse; +import org.apache.commons.logging.Log; +import org.apache.commons.logging.LogFactory; + import org.springframework.security.core.Authentication; import org.springframework.security.web.authentication.session.SessionAuthenticationException; import org.springframework.security.web.authentication.session.SessionAuthenticationStrategy; @@ -34,6 +37,8 @@ import org.springframework.util.Assert; */ public final class CsrfAuthenticationStrategy implements SessionAuthenticationStrategy { + private final Log logger = LogFactory.getLog(getClass()); + private final CsrfTokenRepository csrfTokenRepository; /** @@ -55,6 +60,7 @@ public final class CsrfAuthenticationStrategy implements SessionAuthenticationSt this.csrfTokenRepository.saveToken(newToken, request, response); request.setAttribute(CsrfToken.class.getName(), newToken); request.setAttribute(newToken.getParameterName(), newToken); + this.logger.debug("Replaced CSRF Token"); } } diff --git a/web/src/main/java/org/springframework/security/web/csrf/CsrfFilter.java b/web/src/main/java/org/springframework/security/web/csrf/CsrfFilter.java index 8f91907895..bbbca0bfc0 100644 --- a/web/src/main/java/org/springframework/security/web/csrf/CsrfFilter.java +++ b/web/src/main/java/org/springframework/security/web/csrf/CsrfFilter.java @@ -108,6 +108,10 @@ public final class CsrfFilter extends OncePerRequestFilter { request.setAttribute(CsrfToken.class.getName(), csrfToken); request.setAttribute(csrfToken.getParameterName(), csrfToken); if (!this.requireCsrfProtectionMatcher.matches(request)) { + if (this.logger.isTraceEnabled()) { + this.logger.trace("Did not protect against CSRF since request did not match " + + this.requireCsrfProtectionMatcher); + } filterChain.doFilter(request, response); return; } @@ -170,6 +174,11 @@ public final class CsrfFilter extends OncePerRequestFilter { return !this.allowedMethods.contains(request.getMethod()); } + @Override + public String toString() { + return "CsrfNotRequired " + this.allowedMethods; + } + } } diff --git a/web/src/main/java/org/springframework/security/web/header/writers/ClearSiteDataHeaderWriter.java b/web/src/main/java/org/springframework/security/web/header/writers/ClearSiteDataHeaderWriter.java index d4df85fbee..db3c4be2eb 100644 --- a/web/src/main/java/org/springframework/security/web/header/writers/ClearSiteDataHeaderWriter.java +++ b/web/src/main/java/org/springframework/security/web/header/writers/ClearSiteDataHeaderWriter.java @@ -130,6 +130,11 @@ public final class ClearSiteDataHeaderWriter implements HeaderWriter { return request.isSecure(); } + @Override + public String toString() { + return "Is Secure"; + } + } } diff --git a/web/src/main/java/org/springframework/security/web/header/writers/HpkpHeaderWriter.java b/web/src/main/java/org/springframework/security/web/header/writers/HpkpHeaderWriter.java index 31ee296fde..0422f525c7 100644 --- a/web/src/main/java/org/springframework/security/web/header/writers/HpkpHeaderWriter.java +++ b/web/src/main/java/org/springframework/security/web/header/writers/HpkpHeaderWriter.java @@ -438,6 +438,11 @@ public final class HpkpHeaderWriter implements HeaderWriter { return request.isSecure(); } + @Override + public String toString() { + return "Is Secure"; + } + } } diff --git a/web/src/main/java/org/springframework/security/web/header/writers/HstsHeaderWriter.java b/web/src/main/java/org/springframework/security/web/header/writers/HstsHeaderWriter.java index c88bc5af87..127ea3527d 100644 --- a/web/src/main/java/org/springframework/security/web/header/writers/HstsHeaderWriter.java +++ b/web/src/main/java/org/springframework/security/web/header/writers/HstsHeaderWriter.java @@ -150,8 +150,10 @@ public final class HstsHeaderWriter implements HeaderWriter { @Override public void writeHeaders(HttpServletRequest request, HttpServletResponse response) { if (!this.requestMatcher.matches(request)) { - this.logger.debug(LogMessage.format( - "Not injecting HSTS header since it did not match the requestMatcher %s", this.requestMatcher)); + if (this.logger.isTraceEnabled()) { + this.logger.trace(LogMessage.format("Not injecting HSTS header since it did not match request to [%s]", + this.requestMatcher)); + } return; } if (!response.containsHeader(HSTS_HEADER_NAME)) { @@ -245,6 +247,11 @@ public final class HstsHeaderWriter implements HeaderWriter { return request.isSecure(); } + @Override + public String toString() { + return "Is Secure"; + } + } } diff --git a/web/src/main/java/org/springframework/security/web/savedrequest/DefaultSavedRequest.java b/web/src/main/java/org/springframework/security/web/savedrequest/DefaultSavedRequest.java index aaa8e995c2..ea2358293f 100644 --- a/web/src/main/java/org/springframework/security/web/savedrequest/DefaultSavedRequest.java +++ b/web/src/main/java/org/springframework/security/web/savedrequest/DefaultSavedRequest.java @@ -33,7 +33,6 @@ import com.fasterxml.jackson.databind.annotation.JsonPOJOBuilder; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; -import org.springframework.core.log.LogMessage; import org.springframework.security.web.PortResolver; import org.springframework.security.web.util.UrlUtils; import org.springframework.util.Assert; @@ -212,35 +211,35 @@ public class DefaultSavedRequest implements SavedRequest { * @return true if the request is deemed to match this one. */ public boolean doesRequestMatch(HttpServletRequest request, PortResolver portResolver) { - if (!propertyEquals("pathInfo", this.pathInfo, request.getPathInfo())) { + if (!propertyEquals(this.pathInfo, request.getPathInfo())) { return false; } - if (!propertyEquals("queryString", this.queryString, request.getQueryString())) { + if (!propertyEquals(this.queryString, request.getQueryString())) { return false; } - if (!propertyEquals("requestURI", this.requestURI, request.getRequestURI())) { + if (!propertyEquals(this.requestURI, request.getRequestURI())) { return false; } if (!"GET".equals(request.getMethod()) && "GET".equals(this.method)) { // A save GET should not match an incoming non-GET method return false; } - if (!propertyEquals("serverPort", this.serverPort, portResolver.getServerPort(request))) { + if (!propertyEquals(this.serverPort, portResolver.getServerPort(request))) { return false; } - if (!propertyEquals("requestURL", this.requestURL, request.getRequestURL().toString())) { + if (!propertyEquals(this.requestURL, request.getRequestURL().toString())) { return false; } - if (!propertyEquals("scheme", this.scheme, request.getScheme())) { + if (!propertyEquals(this.scheme, request.getScheme())) { return false; } - if (!propertyEquals("serverName", this.serverName, request.getServerName())) { + if (!propertyEquals(this.serverName, request.getServerName())) { return false; } - if (!propertyEquals("contextPath", this.contextPath, request.getContextPath())) { + if (!propertyEquals(this.contextPath, request.getContextPath())) { return false; } - return propertyEquals("servletPath", this.servletPath, request.getServletPath()); + return propertyEquals(this.servletPath, request.getServletPath()); } @@ -334,26 +333,22 @@ public class DefaultSavedRequest implements SavedRequest { return this.servletPath; } - private boolean propertyEquals(String log, Object arg1, Object arg2) { + private boolean propertyEquals(Object arg1, Object arg2) { if ((arg1 == null) && (arg2 == null)) { - logger.debug(LogMessage.format("%s: both null (property equals)", log)); return true; } if (arg1 == null || arg2 == null) { - logger.debug(LogMessage.format("%s: arg1=%s; arg2=%s (property not equals)", log, arg1, arg2)); return false; } if (arg1.equals(arg2)) { - logger.debug(LogMessage.format("%s: arg1=%s; arg2=%s (property equals)", log, arg1, arg2)); return true; } - logger.debug(LogMessage.format("%s: arg1=%s; arg2=%s (property not equals)", log, arg1, arg2)); return false; } @Override public String toString() { - return "DefaultSavedRequest[" + getRedirectUrl() + "]"; + return "DefaultSavedRequest [" + getRedirectUrl() + "]"; } /** diff --git a/web/src/main/java/org/springframework/security/web/savedrequest/HttpSessionRequestCache.java b/web/src/main/java/org/springframework/security/web/savedrequest/HttpSessionRequestCache.java index a3ac70e4c1..af5d414550 100644 --- a/web/src/main/java/org/springframework/security/web/savedrequest/HttpSessionRequestCache.java +++ b/web/src/main/java/org/springframework/security/web/savedrequest/HttpSessionRequestCache.java @@ -59,7 +59,10 @@ public class HttpSessionRequestCache implements RequestCache { @Override public void saveRequest(HttpServletRequest request, HttpServletResponse response) { if (!this.requestMatcher.matches(request)) { - this.logger.debug("Request not saved as configured RequestMatcher did not match"); + if (this.logger.isTraceEnabled()) { + this.logger.trace( + LogMessage.format("Did not save request since it did not match [%s]", this.requestMatcher)); + } return; } DefaultSavedRequest savedRequest = new DefaultSavedRequest(request, this.portResolver); @@ -68,7 +71,12 @@ public class HttpSessionRequestCache implements RequestCache { // AbstractAuthenticationProcessingFilter // for redirection after successful authentication (SEC-29) request.getSession().setAttribute(this.sessionAttrName, savedRequest); - this.logger.debug(LogMessage.format("DefaultSavedRequest added to Session: %s", savedRequest)); + if (this.logger.isDebugEnabled()) { + this.logger.debug(LogMessage.format("Saved request %s to session", savedRequest.getRedirectUrl())); + } + } + else { + this.logger.trace("Did not save request since there's no session and createSessionAllowed is false"); } } @@ -82,7 +90,7 @@ public class HttpSessionRequestCache implements RequestCache { public void removeRequest(HttpServletRequest currentRequest, HttpServletResponse response) { HttpSession session = currentRequest.getSession(false); if (session != null) { - this.logger.debug("Removing DefaultSavedRequest from session if present"); + this.logger.trace("Removing DefaultSavedRequest from session if present"); session.removeAttribute(this.sessionAttrName); } } @@ -90,18 +98,25 @@ public class HttpSessionRequestCache implements RequestCache { @Override public HttpServletRequest getMatchingRequest(HttpServletRequest request, HttpServletResponse response) { SavedRequest saved = getRequest(request, response); + if (saved == null) { + this.logger.trace("No saved request"); + return null; + } if (!matchesSavedRequest(request, saved)) { - this.logger.debug("saved request doesn't match"); + if (this.logger.isTraceEnabled()) { + this.logger.trace(LogMessage.format("Did not match request %s to the saved one %s", + UrlUtils.buildRequestUrl(request), saved)); + } return null; } removeRequest(request, response); + if (this.logger.isDebugEnabled()) { + this.logger.debug(LogMessage.format("Loaded matching saved request %s", saved.getRedirectUrl())); + } return new SavedRequestAwareWrapper(saved, request); } private boolean matchesSavedRequest(HttpServletRequest request, SavedRequest savedRequest) { - if (savedRequest == null) { - return false; - } if (savedRequest instanceof DefaultSavedRequest) { DefaultSavedRequest defaultSavedRequest = (DefaultSavedRequest) savedRequest; return defaultSavedRequest.doesRequestMatch(request, this.portResolver); diff --git a/web/src/main/java/org/springframework/security/web/session/SessionManagementFilter.java b/web/src/main/java/org/springframework/security/web/session/SessionManagementFilter.java index 510aa072ac..658b9ddb76 100644 --- a/web/src/main/java/org/springframework/security/web/session/SessionManagementFilter.java +++ b/web/src/main/java/org/springframework/security/web/session/SessionManagementFilter.java @@ -112,8 +112,10 @@ public class SessionManagementFilter extends GenericFilterBean { // No security context or authentication present. Check for a session // timeout if (request.getRequestedSessionId() != null && !request.isRequestedSessionIdValid()) { - this.logger.debug( - LogMessage.format("Requested session ID %s is invalid.", request.getRequestedSessionId())); + if (this.logger.isDebugEnabled()) { + this.logger.debug(LogMessage.format("Request requested invalid session id %s", + request.getRequestedSessionId())); + } if (this.invalidSessionStrategy != null) { this.invalidSessionStrategy.onInvalidSessionDetected(request, response); return; diff --git a/web/src/main/java/org/springframework/security/web/util/matcher/AndRequestMatcher.java b/web/src/main/java/org/springframework/security/web/util/matcher/AndRequestMatcher.java index d3c9808677..07682a183f 100644 --- a/web/src/main/java/org/springframework/security/web/util/matcher/AndRequestMatcher.java +++ b/web/src/main/java/org/springframework/security/web/util/matcher/AndRequestMatcher.java @@ -24,7 +24,6 @@ import javax.servlet.http.HttpServletRequest; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; -import org.springframework.core.log.LogMessage; import org.springframework.util.Assert; /** @@ -61,19 +60,16 @@ public final class AndRequestMatcher implements RequestMatcher { @Override public boolean matches(HttpServletRequest request) { for (RequestMatcher matcher : this.requestMatchers) { - this.logger.debug(LogMessage.format("Trying to match using %s", matcher)); if (!matcher.matches(request)) { - this.logger.debug("Did not match"); return false; } } - this.logger.debug("All requestMatchers returned true"); return true; } @Override public String toString() { - return "AndRequestMatcher [requestMatchers=" + this.requestMatchers + "]"; + return "And " + this.requestMatchers; } } diff --git a/web/src/main/java/org/springframework/security/web/util/matcher/AntPathRequestMatcher.java b/web/src/main/java/org/springframework/security/web/util/matcher/AntPathRequestMatcher.java index 4b63dcda1a..9e2968a03f 100644 --- a/web/src/main/java/org/springframework/security/web/util/matcher/AntPathRequestMatcher.java +++ b/web/src/main/java/org/springframework/security/web/util/matcher/AntPathRequestMatcher.java @@ -21,10 +21,6 @@ import java.util.Map; import javax.servlet.http.HttpServletRequest; -import org.apache.commons.logging.Log; -import org.apache.commons.logging.LogFactory; - -import org.springframework.core.log.LogMessage; import org.springframework.http.HttpMethod; import org.springframework.util.AntPathMatcher; import org.springframework.util.Assert; @@ -57,8 +53,6 @@ import org.springframework.web.util.UrlPathHelper; */ public final class AntPathRequestMatcher implements RequestMatcher, RequestVariablesExtractor { - private static final Log logger = LogFactory.getLog(AntPathRequestMatcher.class); - private static final String MATCH_ALL = "/**"; private final Matcher matcher; @@ -148,17 +142,12 @@ public final class AntPathRequestMatcher implements RequestMatcher, RequestVaria public boolean matches(HttpServletRequest request) { if (this.httpMethod != null && StringUtils.hasText(request.getMethod()) && this.httpMethod != valueOf(request.getMethod())) { - logger.debug(LogMessage.of(() -> "Request '" + request.getMethod() + " " + getRequestPath(request) + "'" - + " doesn't match '" + this.httpMethod + " " + this.pattern + "'")); return false; } if (this.pattern.equals(MATCH_ALL)) { - logger.debug(LogMessage - .of(() -> "Request '" + getRequestPath(request) + "' matched by universal pattern '/**'")); return true; } String url = getRequestPath(request); - logger.debug(LogMessage.format("Checking match of request : '%s'; against '%s'", url, this.pattern)); return this.matcher.matches(url); } diff --git a/web/src/main/java/org/springframework/security/web/util/matcher/MediaTypeRequestMatcher.java b/web/src/main/java/org/springframework/security/web/util/matcher/MediaTypeRequestMatcher.java index 7178bc3ed6..6aa80140a6 100644 --- a/web/src/main/java/org/springframework/security/web/util/matcher/MediaTypeRequestMatcher.java +++ b/web/src/main/java/org/springframework/security/web/util/matcher/MediaTypeRequestMatcher.java @@ -27,7 +27,6 @@ import javax.servlet.http.HttpServletRequest; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; -import org.springframework.core.log.LogMessage; import org.springframework.http.MediaType; import org.springframework.util.Assert; import org.springframework.web.HttpMediaTypeNotAcceptableException; @@ -204,31 +203,23 @@ public final class MediaTypeRequestMatcher implements RequestMatcher { httpRequestMediaTypes = this.contentNegotiationStrategy.resolveMediaTypes(new ServletWebRequest(request)); } catch (HttpMediaTypeNotAcceptableException ex) { - this.logger.debug("Failed to parse MediaTypes, returning false", ex); + this.logger.debug("Failed to match request since failed to parse MediaTypes", ex); return false; } - this.logger.debug(LogMessage.format("httpRequestMediaTypes=%s", httpRequestMediaTypes)); for (MediaType httpRequestMediaType : httpRequestMediaTypes) { - this.logger.debug(LogMessage.format("Processing %s", httpRequestMediaType)); if (shouldIgnore(httpRequestMediaType)) { - this.logger.debug("Ignoring"); continue; } if (this.useEquals) { - boolean isEqualTo = this.matchingMediaTypes.contains(httpRequestMediaType); - this.logger.debug(LogMessage.format("isEqualTo %s", isEqualTo)); - return isEqualTo; + return this.matchingMediaTypes.contains(httpRequestMediaType); } for (MediaType matchingMediaType : this.matchingMediaTypes) { boolean isCompatibleWith = matchingMediaType.isCompatibleWith(httpRequestMediaType); - this.logger.debug(LogMessage.format("%s .isCompatibleWith %s = %s", matchingMediaType, - httpRequestMediaType, isCompatibleWith)); if (isCompatibleWith) { return true; } } } - this.logger.debug("Did not match any media types"); return false; } diff --git a/web/src/main/java/org/springframework/security/web/util/matcher/NegatedRequestMatcher.java b/web/src/main/java/org/springframework/security/web/util/matcher/NegatedRequestMatcher.java index d31f6e6e36..3f5e92c6b8 100644 --- a/web/src/main/java/org/springframework/security/web/util/matcher/NegatedRequestMatcher.java +++ b/web/src/main/java/org/springframework/security/web/util/matcher/NegatedRequestMatcher.java @@ -21,7 +21,6 @@ import javax.servlet.http.HttpServletRequest; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; -import org.springframework.core.log.LogMessage; import org.springframework.util.Assert; /** @@ -50,14 +49,12 @@ public class NegatedRequestMatcher implements RequestMatcher { @Override public boolean matches(HttpServletRequest request) { - boolean result = !this.requestMatcher.matches(request); - this.logger.debug(LogMessage.format("matches = %s", result)); - return result; + return !this.requestMatcher.matches(request); } @Override public String toString() { - return "NegatedRequestMatcher [requestMatcher=" + this.requestMatcher + "]"; + return "Not [" + this.requestMatcher + "]"; } } diff --git a/web/src/main/java/org/springframework/security/web/util/matcher/OrRequestMatcher.java b/web/src/main/java/org/springframework/security/web/util/matcher/OrRequestMatcher.java index cacfa15af5..92a2e2eb78 100644 --- a/web/src/main/java/org/springframework/security/web/util/matcher/OrRequestMatcher.java +++ b/web/src/main/java/org/springframework/security/web/util/matcher/OrRequestMatcher.java @@ -21,10 +21,6 @@ import java.util.List; import javax.servlet.http.HttpServletRequest; -import org.apache.commons.logging.Log; -import org.apache.commons.logging.LogFactory; - -import org.springframework.core.log.LogMessage; import org.springframework.util.Assert; /** @@ -36,8 +32,6 @@ import org.springframework.util.Assert; */ public final class OrRequestMatcher implements RequestMatcher { - private final Log logger = LogFactory.getLog(getClass()); - private final List requestMatchers; /** @@ -61,19 +55,16 @@ public final class OrRequestMatcher implements RequestMatcher { @Override public boolean matches(HttpServletRequest request) { for (RequestMatcher matcher : this.requestMatchers) { - this.logger.debug(LogMessage.format("Trying to match using %s", matcher)); if (matcher.matches(request)) { - this.logger.debug("matched"); return true; } } - this.logger.debug("No matches found"); return false; } @Override public String toString() { - return "OrRequestMatcher [requestMatchers=" + this.requestMatchers + "]"; + return "Or " + this.requestMatchers; } } diff --git a/web/src/test/java/org/springframework/security/web/FilterInvocationTests.java b/web/src/test/java/org/springframework/security/web/FilterInvocationTests.java index bd3bb1f5fa..1e96bba4c0 100644 --- a/web/src/test/java/org/springframework/security/web/FilterInvocationTests.java +++ b/web/src/test/java/org/springframework/security/web/FilterInvocationTests.java @@ -57,7 +57,7 @@ public class FilterInvocationTests { assertThat(fi.getHttpResponse()).isEqualTo(response); assertThat(fi.getChain()).isEqualTo(chain); assertThat(fi.getRequestUrl()).isEqualTo("/HelloWorld/some/more/segments.html"); - assertThat(fi.toString()).isEqualTo("FilterInvocation: URL: /HelloWorld/some/more/segments.html"); + assertThat(fi.toString()).isEqualTo("filter invocation [/HelloWorld/some/more/segments.html]"); assertThat(fi.getFullRequestUrl()).isEqualTo("http://localhost/mycontext/HelloWorld/some/more/segments.html"); } @@ -93,7 +93,7 @@ public class FilterInvocationTests { MockHttpServletResponse response = new MockHttpServletResponse(); FilterInvocation fi = new FilterInvocation(request, response, mock(FilterChain.class)); assertThat(fi.getRequestUrl()).isEqualTo("/HelloWorld?foo=bar"); - assertThat(fi.toString()).isEqualTo("FilterInvocation: URL: /HelloWorld?foo=bar"); + assertThat(fi.toString()).isEqualTo("filter invocation [/HelloWorld?foo=bar]"); assertThat(fi.getFullRequestUrl()).isEqualTo("http://localhost/mycontext/HelloWorld?foo=bar"); } @@ -109,7 +109,7 @@ public class FilterInvocationTests { MockHttpServletResponse response = new MockHttpServletResponse(); FilterInvocation fi = new FilterInvocation(request, response, mock(FilterChain.class)); assertThat(fi.getRequestUrl()).isEqualTo("/HelloWorld"); - assertThat(fi.toString()).isEqualTo("FilterInvocation: URL: /HelloWorld"); + assertThat(fi.toString()).isEqualTo("filter invocation [/HelloWorld]"); assertThat(fi.getFullRequestUrl()).isEqualTo("http://localhost/mycontext/HelloWorld"); }