From bf067d679fb5990d6b3d31cee292af171f8a5014 Mon Sep 17 00:00:00 2001 From: Josh Cummings Date: Tue, 8 Sep 2020 13:09:33 -0600 Subject: [PATCH] Add Logging to Resource Server Closes gh-9000 --- .../security/oauth2/jwt/NimbusJwtDecoder.java | 9 +++++++++ .../JwtAuthenticationProvider.java | 7 +++++++ .../JwtGrantedAuthoritiesConverter.java | 10 ++++++++++ ...wtIssuerAuthenticationManagerResolver.java | 20 +++++++++++++++---- .../OpaqueTokenAuthenticationProvider.java | 7 +++++++ .../NimbusOpaqueTokenIntrospector.java | 5 +++++ .../web/BearerTokenAuthenticationFilter.java | 8 +++++++- 7 files changed, 61 insertions(+), 5 deletions(-) diff --git a/oauth2/oauth2-jose/src/main/java/org/springframework/security/oauth2/jwt/NimbusJwtDecoder.java b/oauth2/oauth2-jose/src/main/java/org/springframework/security/oauth2/jwt/NimbusJwtDecoder.java index 97213b90c2..c4e80d2316 100644 --- a/oauth2/oauth2-jose/src/main/java/org/springframework/security/oauth2/jwt/NimbusJwtDecoder.java +++ b/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 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")); } diff --git a/oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/authentication/JwtAuthenticationProvider.java b/oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/authentication/JwtAuthenticationProvider.java index 953fee3c19..5b95141ca6 100644 --- a/oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/authentication/JwtAuthenticationProvider.java +++ b/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 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) { diff --git a/oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/authentication/JwtGrantedAuthoritiesConverter.java b/oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/authentication/JwtGrantedAuthoritiesConverter.java index d126984a21..9e60085019 100644 --- a/oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/authentication/JwtGrantedAuthoritiesConverter.java +++ b/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> { + private final Log logger = LogFactory.getLog(getClass()); + private static final String DEFAULT_AUTHORITY_PREFIX = "SCOPE_"; private static final Collection WELL_KNOWN_AUTHORITIES_CLAIM_NAMES = Arrays.asList("scope", "scp"); @@ -98,8 +104,12 @@ public final class JwtGrantedAuthoritiesConverter implements Converter 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)) { diff --git a/oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/authentication/JwtIssuerAuthenticationManagerResolver.java b/oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/authentication/JwtIssuerAuthenticationManagerResolver.java index 0542792f01..af1cddc205 100644 --- a/oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/authentication/JwtIssuerAuthenticationManagerResolver.java +++ b/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 { + private final Log logger = LogFactory.getLog(getClass()); + private final Map authenticationManagers = new ConcurrentHashMap<>(); private final Predicate 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; } diff --git a/oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/authentication/OpaqueTokenAuthenticationProvider.java b/oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/authentication/OpaqueTokenAuthenticationProvider.java index 6554f2b0bb..d754424531 100644 --- a/oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/authentication/OpaqueTokenAuthenticationProvider.java +++ b/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) { diff --git a/oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/introspection/NimbusOpaqueTokenIntrospector.java b/oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/introspection/NimbusOpaqueTokenIntrospector.java index a1d427712f..4fc09ee93e 100644 --- a/oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/introspection/NimbusOpaqueTokenIntrospector.java +++ b/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> 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); diff --git a/oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/web/BearerTokenAuthenticationFilter.java b/oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/web/BearerTokenAuthenticationFilter.java index e69618545e..02e1d42d4b 100644 --- a/oauth2/oauth2-resource-server/src/main/java/org/springframework/security/oauth2/server/resource/web/BearerTokenAuthenticationFilter.java +++ b/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); } }