From b944209bfec8afd75c9d428668727c623877bc84 Mon Sep 17 00:00:00 2001 From: Sergey Beryozkin Date: Mon, 19 Sep 2022 13:59:42 +0100 Subject: [PATCH] Add more OIDC debug messages --- .../runtime/CodeAuthenticationMechanism.java | 20 +++++++++++++++++-- .../oidc/runtime/OidcIdentityProvider.java | 12 +++++++++++ 2 files changed, 30 insertions(+), 2 deletions(-) diff --git a/extensions/oidc/runtime/src/main/java/io/quarkus/oidc/runtime/CodeAuthenticationMechanism.java b/extensions/oidc/runtime/src/main/java/io/quarkus/oidc/runtime/CodeAuthenticationMechanism.java index 7fdfea032c413..4038ea96c7888 100644 --- a/extensions/oidc/runtime/src/main/java/io/quarkus/oidc/runtime/CodeAuthenticationMechanism.java +++ b/extensions/oidc/runtime/src/main/java/io/quarkus/oidc/runtime/CodeAuthenticationMechanism.java @@ -80,6 +80,7 @@ public Uni authenticate(RoutingContext context, // if the session is already established then try to re-authenticate if (sessionCookie != null) { + LOG.debug("Session cookie is present, starting the reauthentication"); context.put(OidcUtils.SESSION_COOKIE_NAME, sessionCookie.getName()); Uni resolvedContext = resolver.resolveContext(context); return resolvedContext.onItem() @@ -95,6 +96,7 @@ public Uni apply(TenantConfigContext tenantContext) { // if the state cookie is available then try to complete the code flow and start a new session if (stateCookie != null) { + LOG.debug("State cookie is present, processing an expected redirect from the OIDC provider"); if (ResponseMode.FORM_POST == oidcTenantConfig.authentication.responseMode.orElse(ResponseMode.QUERY)) { if (OidcUtils.isFormUrlEncodedRequest(context)) { return OidcUtils.getFormUrlEncodedData(context).onItem() @@ -132,7 +134,7 @@ private Uni processRedirectFromOidc(RoutingContext context, Oi } if (requestParams.contains(OidcConstants.CODE_FLOW_CODE)) { - // start a new session by starting the code flow dance + LOG.debug("Authorization code is present, completing the code flow"); Uni resolvedContext = resolver.resolveContext(context); return resolvedContext.onItem() .transformToUni(new Function>() { @@ -204,6 +206,7 @@ private Uni reAuthenticate(Cookie sessionCookie, @Override public Uni apply(AuthorizationCodeTokens session) { if (isBackChannelLogoutPendingAndValid(configContext, session.getIdToken())) { + LOG.debug("Performing a requested back-channel logout"); return OidcUtils .removeSessionCookie(context, configContext.oidcConfig, sessionCookie.getName(), resolver.getTokenStateManager()) @@ -225,6 +228,7 @@ public Uni apply(Void t) { @Override public Uni apply(SecurityIdentity identity) { if (isLogout(context, configContext)) { + LOG.debug("Performing an RP initiated logout"); fireEvent(SecurityEvent.Type.OIDC_LOGOUT_RP_INITIATED, identity); return buildLogoutRedirectUriUni(context, configContext, session.getIdToken()); @@ -236,6 +240,7 @@ public Uni apply(SecurityIdentity identity) { @Override public Uni apply(Throwable t) { if (t instanceof AuthenticationRedirectException) { + LOG.debug("Redirecting after the reauthentication"); throw (AuthenticationRedirectException) t; } @@ -258,6 +263,7 @@ public Uni apply(Throwable t) { context, identityProviderManager, false, null); } else { + LOG.debug("Token auto-refresh is starting"); return refreshSecurityIdentity(configContext, session.getRefreshToken(), context, @@ -362,6 +368,7 @@ public Uni apply(TenantConfigContext tenantContext) { } public Uni getChallengeInternal(RoutingContext context, TenantConfigContext configContext) { + LOG.debug("Starting an authentication challenge"); return removeSessionCookie(context, configContext.oidcConfig) .chain(new Function>() { @@ -513,6 +520,7 @@ private Uni performCodeFlow(IdentityProviderManager identityPr final String finalUserQuery = userQuery; final String code = requestParams.get(OidcConstants.CODE_FLOW_CODE); + LOG.debug("Exchanging the authorization code for the tokens"); Uni codeFlowTokensUni = getCodeFlowTokensUni(context, configContext, code, stateBean != null ? stateBean.getCodeVerifier() : null); @@ -543,6 +551,7 @@ public Uni apply(final AuthorizationCodeTokens tokens, final T final String idToken = decryptIdTokenIfEncryptedByProvider(configContext, tokens.getIdToken()); + LOG.debug("Authorization code has been exchanged, verifying ID token"); return authenticate(identityProviderManager, context, new IdTokenCredential(idToken, internalIdToken)) .call(new Function>() { @@ -583,7 +592,8 @@ public SecurityIdentity apply(SecurityIdentity identity) { finalUriWithoutQuery.append(finalUserQuery); } String finalRedirectUri = finalUriWithoutQuery.toString(); - LOG.debugf("Final redirect URI: %s", finalRedirectUri); + LOG.debugf("Removing code flow redirect parameters, final redirect URI: %s", + finalRedirectUri); throw new AuthenticationRedirectException(finalRedirectUri); } else { return identity; @@ -593,8 +603,10 @@ public SecurityIdentity apply(SecurityIdentity identity) { @Override public Throwable apply(Throwable tInner) { if (tInner instanceof AuthenticationRedirectException) { + LOG.debugf("Starting the final redirect"); return tInner; } + LOG.debugf("ID token verification has failed: %s", tInner.getMessage()); return new AuthenticationCompletionException(tInner); } }); @@ -641,6 +653,7 @@ private Uni processSuccessfulAuthentication(RoutingContext context, AuthorizationCodeTokens tokens, String idToken, SecurityIdentity securityIdentity) { + LOG.debug("ID token has been verified, removing the existing session cookie if any and creating a new one"); return removeSessionCookie(context, configContext.oidcConfig) .chain(new Function>() { @@ -653,6 +666,7 @@ public Uni apply(Void t) { throw new AuthenticationCompletionException(); } long maxAge = idTokenJson.getLong("exp") - idTokenJson.getLong("iat"); + LOG.debugf("ID token is valid for %d seconds", maxAge); if (configContext.oidcConfig.token.lifespanGrace.isPresent()) { maxAge += configContext.oidcConfig.token.lifespanGrace.getAsInt(); } @@ -847,6 +861,7 @@ public Uni apply(final AuthorizationCodeTokens tokens, final T final String idToken = decryptIdTokenIfEncryptedByProvider(configContext, tokens.getIdToken()); + LOG.debug("Verifying the refreshed ID token"); return authenticate(identityProviderManager, context, new IdTokenCredential(idToken)) .call(new Function>() { @@ -869,6 +884,7 @@ public SecurityIdentity apply(SecurityIdentity identity) { }).onFailure().transform(new Function() { @Override public Throwable apply(Throwable tInner) { + LOG.debugf("Verifying the refreshed ID token failed %s", tInner.getMessage()); return new AuthenticationFailedException(tInner); } }); diff --git a/extensions/oidc/runtime/src/main/java/io/quarkus/oidc/runtime/OidcIdentityProvider.java b/extensions/oidc/runtime/src/main/java/io/quarkus/oidc/runtime/OidcIdentityProvider.java index e41bc034fe395..91a9ece130067 100644 --- a/extensions/oidc/runtime/src/main/java/io/quarkus/oidc/runtime/OidcIdentityProvider.java +++ b/extensions/oidc/runtime/src/main/java/io/quarkus/oidc/runtime/OidcIdentityProvider.java @@ -10,6 +10,7 @@ import javax.enterprise.context.ApplicationScoped; import javax.inject.Inject; +import org.jboss.logging.Logger; import org.jose4j.lang.UnresolvableKeyException; import io.quarkus.oidc.AccessTokenCredential; @@ -36,6 +37,8 @@ @ApplicationScoped public class OidcIdentityProvider implements IdentityProvider { + private static final Logger LOG = Logger.getLogger(OidcIdentityProvider.class); + static final String REFRESH_TOKEN_GRANT_RESPONSE = "refresh_token_grant_response"; static final String NEW_AUTHENTICATION = "new_authentication"; @@ -61,6 +64,7 @@ public Uni authenticate(TokenAuthenticationRequest request, if (!(request.getToken() instanceof AccessTokenCredential || request.getToken() instanceof IdTokenCredential)) { return Uni.createFrom().nullItem(); } + LOG.debug("Starting creating SecurityIdentity"); RoutingContext vertxContext = HttpSecurityUtils.getRoutingContextAttribute(request); vertxContext.put(AuthenticationRequestContext.class.getName(), context); @@ -84,6 +88,7 @@ private Uni authenticate(TokenAuthenticationRequest request, RoutingContext vertxContext, TenantConfigContext resolvedContext) { if (resolvedContext.oidcConfig.publicKey.isPresent()) { + LOG.debug("Performing token verification with a configured public key"); return validateTokenWithoutOidcServer(request, resolvedContext); } else { return validateAllTokensWithOidcServer(vertxContext, request, resolvedContext); @@ -280,21 +285,27 @@ private Uni verifyCodeFlowAccessTokenUni(RoutingContext private Uni verifyTokenUni(TenantConfigContext resolvedContext, String token) { if (OidcUtils.isOpaqueToken(token)) { if (!resolvedContext.oidcConfig.token.allowOpaqueTokenIntrospection) { + LOG.debug("Token is opaque but the opaque token introspection is not allowed"); throw new AuthenticationFailedException(); } + LOG.debug("Starting the opaque token introspection"); return introspectTokenUni(resolvedContext, token); } else if (resolvedContext.provider.getMetadata().getJsonWebKeySetUri() == null || resolvedContext.oidcConfig.token.requireJwtIntrospectionOnly) { // Verify JWT token with the remote introspection + LOG.debug("Starting the JWT token introspection"); return introspectTokenUni(resolvedContext, token); } else { // Verify JWT token with the local JWK keys with a possible remote introspection fallback try { + LOG.debug("Verifying the JWT token with the local JWK keys"); return Uni.createFrom().item(resolvedContext.provider.verifyJwtToken(token)); } catch (Throwable t) { if (t.getCause() instanceof UnresolvableKeyException) { + LOG.debug("No matching JWK key is found, refreshing and repeating the verification"); return refreshJwksAndVerifyTokenUni(resolvedContext, token); } else { + LOG.debugf("Token verification has failed: %s", t.getMessage()); return Uni.createFrom().failure(t); } } @@ -369,6 +380,7 @@ private Uni getUserInfoUni(RoutingContext vertxContext, TokenAuthentic } } + LOG.debug("Requesting UserInfo"); String accessToken = vertxContext.get(OidcConstants.ACCESS_TOKEN_VALUE); if (accessToken == null) { accessToken = request.getToken().getToken();