Add logging for authentication filters

Closes gh-159

Author: Steve Riesenberg

oauth2-authorization-server/src/main/java/org/springframework/security/oauth2/server/authorization/oidc/web/OidcClientRegistrationEndpointFilter.java

@@ -22,6 +22,7 @@
 import javax.servlet.http.HttpServletRequest;
 import javax.servlet.http.HttpServletResponse;
 
+import org.springframework.core.log.LogMessage;
 import org.springframework.http.HttpMethod;
 import org.springframework.http.HttpStatus;
 import org.springframework.http.converter.HttpMessageConverter;
@@ -137,12 +138,18 @@ protected void doFilterInternal(HttpServletRequest request, HttpServletResponse
 
 			this.authenticationSuccessHandler.onAuthenticationSuccess(request, response, clientRegistrationAuthenticationResult);
 		} catch (OAuth2AuthenticationException ex) {
+			if (this.logger.isTraceEnabled()) {
+				this.logger.trace(LogMessage.format("Client registration request failed: %s", ex.getError()), ex);
+			}
 			this.authenticationFailureHandler.onAuthenticationFailure(request, response, ex);
 		} catch (Exception ex) {
 			OAuth2Error error = new OAuth2Error(
 					OAuth2ErrorCodes.INVALID_REQUEST,
 					"OpenID Connect 1.0 Client Registration Error: " + ex.getMessage(),
 					"https://openid.net/specs/openid-connect-registration-1_0.html#RegistrationError");
+			if (this.logger.isTraceEnabled()) {
+				this.logger.trace(error.getDescription(), ex);
+			}
 			this.authenticationFailureHandler.onAuthenticationFailure(request, response,
 					new OAuth2AuthenticationException(error));
 		} finally {

oauth2-authorization-server/src/main/java/org/springframework/security/oauth2/server/authorization/oidc/web/OidcUserInfoEndpointFilter.java

@@ -22,6 +22,7 @@
 import javax.servlet.http.HttpServletRequest;
 import javax.servlet.http.HttpServletResponse;
 
+import org.springframework.core.log.LogMessage;
 import org.springframework.http.HttpMethod;
 import org.springframework.http.HttpStatus;
 import org.springframework.http.converter.HttpMessageConverter;
@@ -116,12 +117,18 @@ protected void doFilterInternal(HttpServletRequest request, HttpServletResponse
 
 			this.authenticationSuccessHandler.onAuthenticationSuccess(request, response, userInfoAuthenticationResult);
 		} catch (OAuth2AuthenticationException ex) {
+			if (this.logger.isTraceEnabled()) {
+				this.logger.trace(LogMessage.format("User info request failed: %s", ex.getError()), ex);
+			}
 			this.authenticationFailureHandler.onAuthenticationFailure(request, response, ex);
 		} catch (Exception ex) {
 			OAuth2Error error = new OAuth2Error(
 					OAuth2ErrorCodes.INVALID_REQUEST,
 					"OpenID Connect 1.0 UserInfo Error: " + ex.getMessage(),
 					"https://openid.net/specs/openid-connect-core-1_0.html#UserInfoError");
+			if (this.logger.isTraceEnabled()) {
+				this.logger.trace(error.getDescription(), ex);
+			}
 			this.authenticationFailureHandler.onAuthenticationFailure(request, response,
 					new OAuth2AuthenticationException(error));
 		} finally {

oauth2-authorization-server/src/main/java/org/springframework/security/oauth2/server/authorization/web/OAuth2AuthorizationEndpointFilter.java

@@ -28,6 +28,7 @@
 import javax.servlet.http.HttpServletRequest;
 import javax.servlet.http.HttpServletResponse;
 
+import org.springframework.core.log.LogMessage;
 import org.springframework.http.HttpMethod;
 import org.springframework.http.HttpStatus;
 import org.springframework.http.MediaType;
@@ -173,6 +174,9 @@ protected void doFilterInternal(HttpServletRequest request, HttpServletResponse
 			}
 
 			if (authenticationResult instanceof OAuth2AuthorizationConsentAuthenticationToken) {
+				if (this.logger.isTraceEnabled()) {
+					this.logger.trace("Authorization consent is required");
+				}
 				sendAuthorizationConsent(request, response,
 						(OAuth2AuthorizationCodeRequestAuthenticationToken) authentication,
 						(OAuth2AuthorizationConsentAuthenticationToken) authenticationResult);
@@ -183,6 +187,9 @@ protected void doFilterInternal(HttpServletRequest request, HttpServletResponse
 					request, response, authenticationResult);
 
 		} catch (OAuth2AuthenticationException ex) {
+			if (this.logger.isTraceEnabled()) {
+				this.logger.trace(LogMessage.format("Authorization request failed: %s", ex.getError()), ex);
+			}
 			this.authenticationFailureHandler.onAuthenticationFailure(request, response, ex);
 		}
 	}
@@ -260,6 +267,9 @@ private void sendAuthorizationConsent(HttpServletRequest request, HttpServletRes
 					.toUriString();
 			this.redirectStrategy.sendRedirect(request, response, redirectUri);
 		} else {
+			if (this.logger.isTraceEnabled()) {
+				this.logger.trace("Displaying generated consent screen");
+			}
 			DefaultConsentPage.displayConsent(request, response, clientId, principal, requestedScopes, authorizedScopes, state);
 		}
 	}
@@ -316,6 +326,10 @@ private void sendErrorResponse(HttpServletRequest request, HttpServletResponse r
 			return;
 		}
 
+		if (this.logger.isTraceEnabled()) {
+			this.logger.trace("Redirecting to client with error");
+		}
+
 		UriComponentsBuilder uriBuilder = UriComponentsBuilder
 				.fromUriString(authorizationCodeRequestAuthentication.getRedirectUri())
 				.queryParam(OAuth2ParameterNames.ERROR, error.getErrorCode());

oauth2-authorization-server/src/main/java/org/springframework/security/oauth2/server/authorization/web/OAuth2ClientAuthenticationFilter.java

@@ -23,6 +23,7 @@
 import javax.servlet.http.HttpServletRequest;
 import javax.servlet.http.HttpServletResponse;
 
+import org.springframework.core.log.LogMessage;
 import org.springframework.http.HttpStatus;
 import org.springframework.http.converter.HttpMessageConverter;
 import org.springframework.http.server.ServletServerHttpResponse;
@@ -123,6 +124,9 @@ protected void doFilterInternal(HttpServletRequest request, HttpServletResponse
 			filterChain.doFilter(request, response);
 
 		} catch (OAuth2AuthenticationException ex) {
+			if (this.logger.isTraceEnabled()) {
+				this.logger.trace(LogMessage.format("Client authentication failed: %s", ex.getError()), ex);
+			}
 			this.authenticationFailureHandler.onAuthenticationFailure(request, response, ex);
 		}
 	}
@@ -166,6 +170,10 @@ private void onAuthenticationSuccess(HttpServletRequest request, HttpServletResp
 		SecurityContext securityContext = SecurityContextHolder.createEmptyContext();
 		securityContext.setAuthentication(authentication);
 		SecurityContextHolder.setContext(securityContext);
+		if (this.logger.isDebugEnabled()) {
+			this.logger.debug(LogMessage.format("Set SecurityContextHolder authentication to %s",
+					authentication.getClass().getSimpleName()));
+		}
 	}
 
 	private void onAuthenticationFailure(HttpServletRequest request, HttpServletResponse response,

oauth2-authorization-server/src/main/java/org/springframework/security/oauth2/server/authorization/web/OAuth2TokenEndpointFilter.java

@@ -25,6 +25,7 @@
 import javax.servlet.http.HttpServletRequest;
 import javax.servlet.http.HttpServletResponse;
 
+import org.springframework.core.log.LogMessage;
 import org.springframework.http.HttpMethod;
 import org.springframework.http.HttpStatus;
 import org.springframework.http.converter.HttpMessageConverter;
@@ -167,6 +168,9 @@ protected void doFilterInternal(HttpServletRequest request, HttpServletResponse
 			this.authenticationSuccessHandler.onAuthenticationSuccess(request, response, accessTokenAuthentication);
 		} catch (OAuth2AuthenticationException ex) {
 			SecurityContextHolder.clearContext();
+			if (this.logger.isTraceEnabled()) {
+				this.logger.trace(LogMessage.format("Token request failed: %s", ex.getError()), ex);
+			}
 			this.authenticationFailureHandler.onAuthenticationFailure(request, response, ex);
 		}
 	}

oauth2-authorization-server/src/main/java/org/springframework/security/oauth2/server/authorization/web/OAuth2TokenIntrospectionEndpointFilter.java

@@ -22,6 +22,7 @@
 import javax.servlet.http.HttpServletRequest;
 import javax.servlet.http.HttpServletResponse;
 
+import org.springframework.core.log.LogMessage;
 import org.springframework.http.HttpMethod;
 import org.springframework.http.HttpStatus;
 import org.springframework.http.converter.HttpMessageConverter;
@@ -113,6 +114,9 @@ protected void doFilterInternal(HttpServletRequest request, HttpServletResponse
 			this.authenticationSuccessHandler.onAuthenticationSuccess(request, response, tokenIntrospectionAuthenticationResult);
 		} catch (OAuth2AuthenticationException ex) {
 			SecurityContextHolder.clearContext();
+			if (this.logger.isTraceEnabled()) {
+				this.logger.trace(LogMessage.format("Token introspection request failed: %s", ex.getError()), ex);
+			}
 			this.authenticationFailureHandler.onAuthenticationFailure(request, response, ex);
 		}
 	}

oauth2-authorization-server/src/main/java/org/springframework/security/oauth2/server/authorization/web/OAuth2TokenRevocationEndpointFilter.java

@@ -22,6 +22,7 @@
 import javax.servlet.http.HttpServletRequest;
 import javax.servlet.http.HttpServletResponse;
 
+import org.springframework.core.log.LogMessage;
 import org.springframework.http.HttpMethod;
 import org.springframework.http.HttpStatus;
 import org.springframework.http.converter.HttpMessageConverter;
@@ -110,6 +111,9 @@ protected void doFilterInternal(HttpServletRequest request, HttpServletResponse
 			this.authenticationSuccessHandler.onAuthenticationSuccess(request, response, tokenRevocationAuthenticationResult);
 		} catch (OAuth2AuthenticationException ex) {
 			SecurityContextHolder.clearContext();
+			if (this.logger.isTraceEnabled()) {
+				this.logger.trace(LogMessage.format("Token revocation request failed: %s", ex.getError()), ex);
+			}
 			this.authenticationFailureHandler.onAuthenticationFailure(request, response, ex);
 		}
 	}