Add Logging to Resource Server

Closes gh-9000

oauth2/oauth2-jose/src/main/java/org/springframework/security/oauth2/jwt/NimbusJwtDecoder.java

@@ -51,6 +51,8 @@ import com.nimbusds.jwt.PlainJWT;
 import com.nimbusds.jwt.proc.ConfigurableJWTProcessor;
 import com.nimbusds.jwt.proc.DefaultJWTProcessor;
 import com.nimbusds.jwt.proc.JWTProcessor;
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
 
 import org.springframework.cache.Cache;
 import org.springframework.core.convert.converter.Converter;
@@ -80,6 +82,8 @@ import org.springframework.web.client.RestTemplate;
  */
 public final class NimbusJwtDecoder implements JwtDecoder {
 
+	private final Log logger = LogFactory.getLog(getClass());
+
 	private static final String DECODING_ERROR_MESSAGE_TEMPLATE = "An error occurred while attempting to decode the Jwt: %s";
 
 	private final JWTProcessor<SecurityContext> jwtProcessor;
@@ -126,6 +130,7 @@ public final class NimbusJwtDecoder implements JwtDecoder {
 	public Jwt decode(String token) throws JwtException {
 		JWT jwt = parse(token);
 		if (jwt instanceof PlainJWT) {
+			this.logger.trace("Failed to decode unsigned token");
 			throw new BadJwtException("Unsupported algorithm of " + jwt.getHeader().getAlgorithm());
 		}
 		Jwt createdJwt = createJwt(token, jwt);
@@ -137,6 +142,7 @@ public final class NimbusJwtDecoder implements JwtDecoder {
 			return JWTParser.parse(token);
 		}
 		catch (Exception ex) {
+			this.logger.trace("Failed to parse token", ex);
 			throw new BadJwtException(String.format(DECODING_ERROR_MESSAGE_TEMPLATE, ex.getMessage()), ex);
 		}
 	}
@@ -155,15 +161,18 @@ public final class NimbusJwtDecoder implements JwtDecoder {
 			// @formatter:on
 		}
 		catch (RemoteKeySourceException ex) {
+			this.logger.trace("Failed to retrieve JWK set", ex);
 			if (ex.getCause() instanceof ParseException) {
 				throw new JwtException(String.format(DECODING_ERROR_MESSAGE_TEMPLATE, "Malformed Jwk set"));
 			}
 			throw new JwtException(String.format(DECODING_ERROR_MESSAGE_TEMPLATE, ex.getMessage()), ex);
 		}
 		catch (JOSEException ex) {
+			this.logger.trace("Failed to process JWT", ex);
 			throw new JwtException(String.format(DECODING_ERROR_MESSAGE_TEMPLATE, ex.getMessage()), ex);
 		}
 		catch (Exception ex) {
+			this.logger.trace("Failed to process JWT", ex);
 			if (ex.getCause() instanceof ParseException) {
 				throw new BadJwtException(String.format(DECODING_ERROR_MESSAGE_TEMPLATE, "Malformed payload"));
 			}

oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/authentication/JwtAuthenticationProvider.java

@@ -18,6 +18,9 @@ package org.springframework.security.oauth2.server.resource.authentication;
 
 import java.util.Collection;
 
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
+
 import org.springframework.core.convert.converter.Converter;
 import org.springframework.security.authentication.AbstractAuthenticationToken;
 import org.springframework.security.authentication.AuthenticationProvider;
@@ -60,6 +63,8 @@ import org.springframework.util.Assert;
  */
 public final class JwtAuthenticationProvider implements AuthenticationProvider {
 
+	private final Log logger = LogFactory.getLog(getClass());
+
 	private final JwtDecoder jwtDecoder;
 
 	private Converter<Jwt, ? extends AbstractAuthenticationToken> jwtAuthenticationConverter = new JwtAuthenticationConverter();
@@ -83,6 +88,7 @@ public final class JwtAuthenticationProvider implements AuthenticationProvider {
 		Jwt jwt = getJwt(bearer);
 		AbstractAuthenticationToken token = this.jwtAuthenticationConverter.convert(jwt);
 		token.setDetails(bearer.getDetails());
+		this.logger.debug("Authenticated token");
 		return token;
 	}
 
@@ -91,6 +97,7 @@ public final class JwtAuthenticationProvider implements AuthenticationProvider {
 			return this.jwtDecoder.decode(bearer.getToken());
 		}
 		catch (BadJwtException failed) {
+			this.logger.debug("Failed to authenticate since the JWT was invalid");
 			throw new InvalidBearerTokenException(failed.getMessage(), failed);
 		}
 		catch (JwtException failed) {

oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/authentication/JwtGrantedAuthoritiesConverter.java

@@ -21,7 +21,11 @@ import java.util.Arrays;
 import java.util.Collection;
 import java.util.Collections;
 
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
+
 import org.springframework.core.convert.converter.Converter;
+import org.springframework.core.log.LogMessage;
 import org.springframework.security.core.GrantedAuthority;
 import org.springframework.security.core.authority.SimpleGrantedAuthority;
 import org.springframework.security.oauth2.jwt.Jwt;
@@ -37,6 +41,8 @@ import org.springframework.util.StringUtils;
  */
 public final class JwtGrantedAuthoritiesConverter implements Converter<Jwt, Collection<GrantedAuthority>> {
 
+	private final Log logger = LogFactory.getLog(getClass());
+
 	private static final String DEFAULT_AUTHORITY_PREFIX = "SCOPE_";
 
 	private static final Collection<String> WELL_KNOWN_AUTHORITIES_CLAIM_NAMES = Arrays.asList("scope", "scp");
@@ -98,8 +104,12 @@ public final class JwtGrantedAuthoritiesConverter implements Converter<Jwt, Coll
 	private Collection<String> getAuthorities(Jwt jwt) {
 		String claimName = getAuthoritiesClaimName(jwt);
 		if (claimName == null) {
+			this.logger.trace("Returning no authorities since could not find any claims that might contain scopes");
 			return Collections.emptyList();
 		}
+		if (this.logger.isTraceEnabled()) {
+			this.logger.trace(LogMessage.format("Looking for scopes in claim %s", claimName));
+		}
 		Object authorities = jwt.getClaim(claimName);
 		if (authorities instanceof String) {
 			if (StringUtils.hasText((String) authorities)) {

oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/authentication/JwtIssuerAuthenticationManagerResolver.java

@@ -26,8 +26,11 @@ import java.util.function.Predicate;
 import javax.servlet.http.HttpServletRequest;
 
 import com.nimbusds.jwt.JWTParser;
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
 
 import org.springframework.core.convert.converter.Converter;
+import org.springframework.core.log.LogMessage;
 import org.springframework.lang.NonNull;
 import org.springframework.security.authentication.AuthenticationManager;
 import org.springframework.security.authentication.AuthenticationManagerResolver;
@@ -151,6 +154,8 @@ public final class JwtIssuerAuthenticationManagerResolver implements Authenticat
 	private static class TrustedIssuerJwtAuthenticationManagerResolver
 			implements AuthenticationManagerResolver<String> {
 
+		private final Log logger = LogFactory.getLog(getClass());
+
 		private final Map<String, AuthenticationManager> authenticationManagers = new ConcurrentHashMap<>();
 
 		private final Predicate<String> trustedIssuer;
@@ -162,10 +167,17 @@ public final class JwtIssuerAuthenticationManagerResolver implements Authenticat
 		@Override
 		public AuthenticationManager resolve(String issuer) {
 			if (this.trustedIssuer.test(issuer)) {
-				return this.authenticationManagers.computeIfAbsent(issuer, (k) -> {
-					JwtDecoder jwtDecoder = JwtDecoders.fromIssuerLocation(issuer);
-					return new JwtAuthenticationProvider(jwtDecoder)::authenticate;
-				});
+				AuthenticationManager authenticationManager = this.authenticationManagers.computeIfAbsent(issuer,
+						(k) -> {
+							this.logger.debug("Constructing AuthenticationManager");
+							JwtDecoder jwtDecoder = JwtDecoders.fromIssuerLocation(issuer);
+							return new JwtAuthenticationProvider(jwtDecoder)::authenticate;
+						});
+				this.logger.debug(LogMessage.format("Resolved AuthenticationManager for issuer '%s'", issuer));
+				return authenticationManager;
+			}
+			else {
+				this.logger.debug("Did not resolve AuthenticationManager since issuer is not trusted");
 			}
 			return null;
 		}

oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/authentication/OpaqueTokenAuthenticationProvider.java

@@ -19,6 +19,9 @@ package org.springframework.security.oauth2.server.resource.authentication;
 import java.time.Instant;
 import java.util.Collection;
 
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
+
 import org.springframework.security.authentication.AbstractAuthenticationToken;
 import org.springframework.security.authentication.AuthenticationProvider;
 import org.springframework.security.authentication.AuthenticationServiceException;
@@ -61,6 +64,8 @@ import org.springframework.util.Assert;
  */
 public final class OpaqueTokenAuthenticationProvider implements AuthenticationProvider {
 
+	private final Log logger = LogFactory.getLog(getClass());
+
 	private OpaqueTokenIntrospector introspector;
 
 	/**
@@ -89,6 +94,7 @@ public final class OpaqueTokenAuthenticationProvider implements AuthenticationPr
 		OAuth2AuthenticatedPrincipal principal = getOAuth2AuthenticatedPrincipal(bearer);
 		AbstractAuthenticationToken result = convert(principal, bearer.getToken());
 		result.setDetails(bearer.getDetails());
+		this.logger.debug("Authenticated token");
 		return result;
 	}
 
@@ -97,6 +103,7 @@ public final class OpaqueTokenAuthenticationProvider implements AuthenticationPr
 			return this.introspector.introspect(bearer.getToken());
 		}
 		catch (BadOpaqueTokenException failed) {
+			this.logger.debug("Failed to authenticate since token was invalid");
 			throw new InvalidBearerTokenException(failed.getMessage());
 		}
 		catch (OAuth2IntrospectionException failed) {

oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/introspection/NimbusOpaqueTokenIntrospector.java

@@ -29,6 +29,8 @@ import com.nimbusds.oauth2.sdk.TokenIntrospectionResponse;
 import com.nimbusds.oauth2.sdk.TokenIntrospectionSuccessResponse;
 import com.nimbusds.oauth2.sdk.http.HTTPResponse;
 import com.nimbusds.oauth2.sdk.id.Audience;
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
 
 import org.springframework.core.convert.converter.Converter;
 import org.springframework.http.HttpHeaders;
@@ -58,6 +60,8 @@ import org.springframework.web.client.RestTemplate;
  */
 public class NimbusOpaqueTokenIntrospector implements OpaqueTokenIntrospector {
 
+	private final Log logger = LogFactory.getLog(getClass());
+
 	private Converter<String, RequestEntity<?>> requestEntityConverter;
 
 	private RestOperations restOperations;
@@ -128,6 +132,7 @@ public class NimbusOpaqueTokenIntrospector implements OpaqueTokenIntrospector {
 		// relying solely on the authorization server to validate this token (not checking
 		// 'exp', for example)
 		if (!introspectionSuccessResponse.isActive()) {
+			this.logger.trace("Did not validate token since it is inactive");
 			throw new BadOpaqueTokenException("Provided token isn't active");
 		}
 		return convertClaimsSet(introspectionSuccessResponse);

oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/web/BearerTokenAuthenticationFilter.java

@@ -23,6 +23,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.authentication.AuthenticationDetailsSource;
 import org.springframework.security.authentication.AuthenticationManager;
 import org.springframework.security.authentication.AuthenticationManagerResolver;
@@ -105,10 +106,12 @@ public final class BearerTokenAuthenticationFilter extends OncePerRequestFilter
 			token = this.bearerTokenResolver.resolve(request);
 		}
 		catch (OAuth2AuthenticationException invalid) {
+			this.logger.trace("Sending to authentication entry point since failed to resolve bearer token", invalid);
 			this.authenticationEntryPoint.commence(request, response, invalid);
 			return;
 		}
 		if (token == null) {
+			this.logger.trace("Did not process request since did not find bearer token");
 			filterChain.doFilter(request, response);
 			return;
 		}
@@ -120,11 +123,14 @@ public final class BearerTokenAuthenticationFilter extends OncePerRequestFilter
 			SecurityContext context = SecurityContextHolder.createEmptyContext();
 			context.setAuthentication(authenticationResult);
 			SecurityContextHolder.setContext(context);
+			if (this.logger.isDebugEnabled()) {
+				this.logger.debug(LogMessage.format("Set SecurityContextHolder to %s", authenticationResult));
+			}
 			filterChain.doFilter(request, response);
 		}
 		catch (AuthenticationException failed) {
 			SecurityContextHolder.clearContext();
-			this.logger.debug("Authentication request for failed!", failed);
+			this.logger.trace("Failed to process authentication request", failed);
 			this.authenticationFailureHandler.onAuthenticationFailure(request, response, failed);
 		}
 	}