Add logging for authentication providers

Issue spring-projectsgh-159

Author: Steve Riesenberg

oauth2-authorization-server/src/main/java/org/springframework/security/oauth2/server/authorization/authentication/ClientSecretAuthenticationProvider.java

@@ -17,6 +17,9 @@
 
 import java.time.Instant;
 
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
+
 import org.springframework.security.authentication.AuthenticationProvider;
 import org.springframework.security.core.Authentication;
 import org.springframework.security.core.AuthenticationException;
@@ -47,6 +50,7 @@
  */
 public final class ClientSecretAuthenticationProvider implements AuthenticationProvider {
 	private static final String ERROR_URI = "https://datatracker.ietf.org/doc/html/rfc6749#section-3.2.1";
+	private final Log logger = LogFactory.getLog(getClass());
 	private final RegisteredClientRepository registeredClientRepository;
 	private final CodeVerifierAuthenticator codeVerifierAuthenticator;
 	private PasswordEncoder passwordEncoder;
@@ -95,6 +99,8 @@ public Authentication authenticate(Authentication authentication) throws Authent
 			throwInvalidClient(OAuth2ParameterNames.CLIENT_ID);
 		}
 
+		this.logger.trace("Retrieved registered client");
+
 		if (!registeredClient.getClientAuthenticationMethods().contains(
 				clientAuthentication.getClientAuthenticationMethod())) {
 			throwInvalidClient("authentication_method");
@@ -114,9 +120,13 @@ public Authentication authenticate(Authentication authentication) throws Authent
 			throwInvalidClient("client_secret_expires_at");
 		}
 
+		this.logger.trace("Validated client authentication parameters");
+
 		// Validate the "code_verifier" parameter for the confidential client, if available
 		this.codeVerifierAuthenticator.authenticateIfAvailable(clientAuthentication, registeredClient);
 
+		this.logger.trace("Authenticated client secret");
+
 		return new OAuth2ClientAuthenticationToken(registeredClient,
 				clientAuthentication.getClientAuthenticationMethod(), clientAuthentication.getCredentials());
 	}

oauth2-authorization-server/src/main/java/org/springframework/security/oauth2/server/authorization/authentication/CodeVerifierAuthenticator.java

@@ -21,6 +21,9 @@
 import java.util.Base64;
 import java.util.Map;
 
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
+
 import org.springframework.security.oauth2.core.AuthorizationGrantType;
 import org.springframework.security.oauth2.core.OAuth2AuthenticationException;
 import org.springframework.security.oauth2.core.OAuth2Error;
@@ -47,6 +50,7 @@
  */
 final class CodeVerifierAuthenticator {
 	private static final OAuth2TokenType AUTHORIZATION_CODE_TOKEN_TYPE = new OAuth2TokenType(OAuth2ParameterNames.CODE);
+	private final Log logger = LogFactory.getLog(getClass());
 	private final OAuth2AuthorizationService authorizationService;
 
 	CodeVerifierAuthenticator(OAuth2AuthorizationService authorizationService) {
@@ -81,6 +85,8 @@ private boolean authenticate(OAuth2ClientAuthenticationToken clientAuthenticatio
 			throwInvalidGrant(OAuth2ParameterNames.CODE);
 		}
 
+		this.logger.trace("Retrieved authorization with authorization code");
+
 		OAuth2AuthorizationRequest authorizationRequest = authorization.getAttribute(
 				OAuth2AuthorizationRequest.class.getName());
 
@@ -90,17 +96,22 @@ private boolean authenticate(OAuth2ClientAuthenticationToken clientAuthenticatio
 			if (registeredClient.getClientSettings().isRequireProofKey()) {
 				throwInvalidGrant(PkceParameterNames.CODE_CHALLENGE);
 			} else {
+				this.logger.trace("Did not authenticate code verifier since requireProofKey=false");
 				return false;
 			}
 		}
 
+		this.logger.trace("Validated code verifier parameters");
+
 		String codeChallengeMethod = (String) authorizationRequest.getAdditionalParameters()
 				.get(PkceParameterNames.CODE_CHALLENGE_METHOD);
 		String codeVerifier = (String) parameters.get(PkceParameterNames.CODE_VERIFIER);
 		if (!codeVerifierValid(codeVerifier, codeChallenge, codeChallengeMethod)) {
 			throwInvalidGrant(PkceParameterNames.CODE_VERIFIER);
 		}
 
+		this.logger.trace("Authenticated code verifier");
+
 		return true;
 	}
 

oauth2-authorization-server/src/main/java/org/springframework/security/oauth2/server/authorization/authentication/JwtClientAssertionAuthenticationProvider.java

@@ -15,6 +15,9 @@
  */
 package org.springframework.security.oauth2.server.authorization.authentication;
 
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
+
 import org.springframework.security.authentication.AuthenticationProvider;
 import org.springframework.security.core.Authentication;
 import org.springframework.security.core.AuthenticationException;
@@ -48,6 +51,7 @@
  */
 public final class JwtClientAssertionAuthenticationProvider implements AuthenticationProvider {
 	private static final String ERROR_URI = "https://datatracker.ietf.org/doc/html/rfc6749#section-3.2.1";
+	private final Log logger = LogFactory.getLog(getClass());
 	private static final ClientAuthenticationMethod JWT_CLIENT_ASSERTION_AUTHENTICATION_METHOD =
 			new ClientAuthenticationMethod("urn:ietf:params:oauth:client-assertion-type:jwt-bearer");
 	private final RegisteredClientRepository registeredClientRepository;
@@ -84,6 +88,8 @@ public Authentication authenticate(Authentication authentication) throws Authent
 			throwInvalidClient(OAuth2ParameterNames.CLIENT_ID);
 		}
 
+		this.logger.trace("Retrieved registered client");
+
 		if (!registeredClient.getClientAuthenticationMethods().contains(ClientAuthenticationMethod.PRIVATE_KEY_JWT) &&
 				!registeredClient.getClientAuthenticationMethods().contains(ClientAuthenticationMethod.CLIENT_SECRET_JWT)) {
 			throwInvalidClient("authentication_method");
@@ -101,6 +107,8 @@ public Authentication authenticate(Authentication authentication) throws Authent
 			throwInvalidClient(OAuth2ParameterNames.CLIENT_ASSERTION, ex);
 		}
 
+		this.logger.trace("Validated client authentication parameters");
+
 		// Validate the "code_verifier" parameter for the confidential client, if available
 		this.codeVerifierAuthenticator.authenticateIfAvailable(clientAuthentication, registeredClient);
 
@@ -109,6 +117,8 @@ public Authentication authenticate(Authentication authentication) throws Authent
 						ClientAuthenticationMethod.PRIVATE_KEY_JWT :
 						ClientAuthenticationMethod.CLIENT_SECRET_JWT;
 
+		this.logger.trace("Authenticated client assertion");
+
 		return new OAuth2ClientAuthenticationToken(registeredClient, clientAuthenticationMethod, jwtAssertion);
 	}
 

oauth2-authorization-server/src/main/java/org/springframework/security/oauth2/server/authorization/authentication/OAuth2AuthorizationCodeAuthenticationProvider.java

@@ -20,6 +20,10 @@
 import java.util.HashMap;
 import java.util.Map;
 
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
+
+import org.springframework.core.log.LogMessage;
 import org.springframework.security.authentication.AuthenticationProvider;
 import org.springframework.security.core.Authentication;
 import org.springframework.security.core.AuthenticationException;
@@ -68,6 +72,7 @@
  */
 public final class OAuth2AuthorizationCodeAuthenticationProvider implements AuthenticationProvider {
 	private static final String ERROR_URI = "https://datatracker.ietf.org/doc/html/rfc6749#section-5.2";
+	private final Log logger = LogFactory.getLog(getClass());
 	private static final OAuth2TokenType AUTHORIZATION_CODE_TOKEN_TYPE =
 			new OAuth2TokenType(OAuth2ParameterNames.CODE);
 	private static final OAuth2TokenType ID_TOKEN_TOKEN_TYPE =
@@ -99,11 +104,16 @@ public Authentication authenticate(Authentication authentication) throws Authent
 				getAuthenticatedClientElseThrowInvalidClient(authorizationCodeAuthentication);
 		RegisteredClient registeredClient = clientPrincipal.getRegisteredClient();
 
+		this.logger.trace("Retrieved registered client");
+
 		OAuth2Authorization authorization = this.authorizationService.findByToken(
 				authorizationCodeAuthentication.getCode(), AUTHORIZATION_CODE_TOKEN_TYPE);
 		if (authorization == null) {
 			throw new OAuth2AuthenticationException(OAuth2ErrorCodes.INVALID_GRANT);
 		}
+
+		this.logger.trace("Retrieved authorization with authorization code");
+
 		OAuth2Authorization.Token<OAuth2AuthorizationCode> authorizationCode =
 				authorization.getToken(OAuth2AuthorizationCode.class);
 
@@ -115,6 +125,9 @@ public Authentication authenticate(Authentication authentication) throws Authent
 				// Invalidate the authorization code given that a different client is attempting to use it
 				authorization = OAuth2AuthenticationProviderUtils.invalidate(authorization, authorizationCode.getToken());
 				this.authorizationService.save(authorization);
+				if (this.logger.isWarnEnabled()) {
+					this.logger.warn(LogMessage.format("Invalidated authorization code used by registered client '%s'", registeredClient.getId()));
+				}
 			}
 			throw new OAuth2AuthenticationException(OAuth2ErrorCodes.INVALID_GRANT);
 		}
@@ -128,6 +141,8 @@ public Authentication authenticate(Authentication authentication) throws Authent
 			throw new OAuth2AuthenticationException(OAuth2ErrorCodes.INVALID_GRANT);
 		}
 
+		this.logger.trace("Validated token request parameters");
+
 		// @formatter:off
 		DefaultOAuth2TokenContext.Builder tokenContextBuilder = DefaultOAuth2TokenContext.builder()
 				.registeredClient(registeredClient)
@@ -149,6 +164,9 @@ public Authentication authenticate(Authentication authentication) throws Authent
 					"The token generator failed to generate the access token.", ERROR_URI);
 			throw new OAuth2AuthenticationException(error);
 		}
+
+		this.logger.trace("Generated access token");
+
 		OAuth2AccessToken accessToken = new OAuth2AccessToken(OAuth2AccessToken.TokenType.BEARER,
 				generatedAccessToken.getTokenValue(), generatedAccessToken.getIssuedAt(),
 				generatedAccessToken.getExpiresAt(), tokenContext.getAuthorizedScopes());
@@ -172,6 +190,9 @@ public Authentication authenticate(Authentication authentication) throws Authent
 						"The token generator failed to generate the refresh token.", ERROR_URI);
 				throw new OAuth2AuthenticationException(error);
 			}
+
+			this.logger.trace("Generated refresh token");
+
 			refreshToken = (OAuth2RefreshToken) generatedRefreshToken;
 			authorizationBuilder.refreshToken(refreshToken);
 		}
@@ -191,6 +212,9 @@ public Authentication authenticate(Authentication authentication) throws Authent
 						"The token generator failed to generate the ID token.", ERROR_URI);
 				throw new OAuth2AuthenticationException(error);
 			}
+
+			this.logger.trace("Generated id token");
+
 			idToken = new OidcIdToken(generatedIdToken.getTokenValue(), generatedIdToken.getIssuedAt(),
 					generatedIdToken.getExpiresAt(), ((Jwt) generatedIdToken).getClaims());
 			authorizationBuilder.token(idToken, (metadata) ->
@@ -206,12 +230,16 @@ public Authentication authenticate(Authentication authentication) throws Authent
 
 		this.authorizationService.save(authorization);
 
+		this.logger.trace("Saved authorization");
+
 		Map<String, Object> additionalParameters = Collections.emptyMap();
 		if (idToken != null) {
 			additionalParameters = new HashMap<>();
 			additionalParameters.put(OidcParameterNames.ID_TOKEN, idToken.getTokenValue());
 		}
 
+		this.logger.trace("Authenticated token request");
+
 		return new OAuth2AccessTokenAuthenticationToken(
 				registeredClient, clientPrincipal, accessToken, refreshToken, additionalParameters);
 	}

oauth2-authorization-server/src/main/java/org/springframework/security/oauth2/server/authorization/authentication/OAuth2AuthorizationCodeRequestAuthenticationProvider.java

@@ -20,6 +20,9 @@
 import java.util.Set;
 import java.util.function.Consumer;
 
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
+
 import org.springframework.security.authentication.AnonymousAuthenticationToken;
 import org.springframework.security.authentication.AuthenticationProvider;
 import org.springframework.security.core.Authentication;
@@ -67,6 +70,7 @@
 public final class OAuth2AuthorizationCodeRequestAuthenticationProvider implements AuthenticationProvider {
 	private static final String ERROR_URI = "https://datatracker.ietf.org/doc/html/rfc6749#section-4.1.2.1";
 	private static final String PKCE_ERROR_URI = "https://datatracker.ietf.org/doc/html/rfc7636#section-4.4.1";
+	private final Log logger = LogFactory.getLog(getClass());
 	private static final StringKeyGenerator DEFAULT_STATE_GENERATOR =
 			new Base64StringKeyGenerator(Base64.getUrlEncoder());
 	private final RegisteredClientRepository registeredClientRepository;
@@ -105,6 +109,8 @@ public Authentication authenticate(Authentication authentication) throws Authent
 					authorizationCodeRequestAuthentication, null);
 		}
 
+		this.logger.trace("Retrieved registered client");
+
 		OAuth2AuthorizationCodeRequestAuthenticationContext authenticationContext =
 				OAuth2AuthorizationCodeRequestAuthenticationContext.with(authorizationCodeRequestAuthentication)
 						.registeredClient(registeredClient)
@@ -129,13 +135,16 @@ public Authentication authenticate(Authentication authentication) throws Authent
 					authorizationCodeRequestAuthentication, registeredClient, null);
 		}
 
+		this.logger.trace("Validated authorization code request parameters");
+
 		// ---------------
 		// The request is valid - ensure the resource owner is authenticated
 		// ---------------
 
 		Authentication principal = (Authentication) authorizationCodeRequestAuthentication.getPrincipal();
 		if (!isPrincipalAuthenticated(principal)) {
 			// Return the authorization request as-is where isAuthenticated() is false
+			this.logger.trace("Did not authenticate authorization code request since principal not authenticated");
 			return authorizationCodeRequestAuthentication;
 		}
 
@@ -156,11 +165,16 @@ public Authentication authenticate(Authentication authentication) throws Authent
 			OAuth2Authorization authorization = authorizationBuilder(registeredClient, principal, authorizationRequest)
 					.attribute(OAuth2ParameterNames.STATE, state)
 					.build();
+
+			logger.trace("Generated authorization consent state");
+
 			this.authorizationService.save(authorization);
 
 			Set<String> currentAuthorizedScopes = currentAuthorizationConsent != null ?
 					currentAuthorizationConsent.getScopes() : null;
 
+			this.logger.trace("Saved authorization");
+
 			return new OAuth2AuthorizationConsentAuthenticationToken(authorizationRequest.getAuthorizationUri(),
 					registeredClient.getClientId(), principal, state, currentAuthorizedScopes, null);
 		}
@@ -174,17 +188,23 @@ public Authentication authenticate(Authentication authentication) throws Authent
 			throw new OAuth2AuthorizationCodeRequestAuthenticationException(error, null);
 		}
 
+		this.logger.trace("Generated authorization code");
+
 		OAuth2Authorization authorization = authorizationBuilder(registeredClient, principal, authorizationRequest)
 				.authorizedScopes(authorizationRequest.getScopes())
 				.token(authorizationCode)
 				.build();
 		this.authorizationService.save(authorization);
 
+		this.logger.trace("Saved authorization");
+
 		String redirectUri = authorizationRequest.getRedirectUri();
 		if (!StringUtils.hasText(redirectUri)) {
 			redirectUri = registeredClient.getRedirectUris().iterator().next();
 		}
 
+		this.logger.trace("Authenticated authorization code request");
+
 		return new OAuth2AuthorizationCodeRequestAuthenticationToken(authorizationRequest.getAuthorizationUri(),
 				registeredClient.getClientId(), principal, authorizationCode, redirectUri,
 				authorizationRequest.getState(), authorizationRequest.getScopes());