From ccade622898e3e14c2ff52f8bfeaa9d4d265a6a6 Mon Sep 17 00:00:00 2001 From: cgeorgilakis-grnet Date: Fri, 27 Oct 2023 13:46:20 +0300 Subject: [PATCH] Enhance error logs and error events during UserInfo endpoint and Token Introspection failure Closes #24344 Signed-off-by: cgeorgilakis-grnet --- .../main/java/org/keycloak/events/Errors.java | 2 ++ .../oidc/TokenIntrospectionProvider.java | 3 +- .../introspect/RPTIntrospectionProvider.java | 11 +++++-- .../AccessTokenIntrospectionProvider.java | 19 ++++++++--- .../keycloak/protocol/oidc/TokenManager.java | 32 ++++++++++++++++--- .../endpoints/TokenIntrospectionEndpoint.java | 2 +- .../services/util/UserSessionUtil.java | 14 ++++++-- .../testsuite/oauth/ServiceAccountTest.java | 3 +- 8 files changed, 70 insertions(+), 16 deletions(-) diff --git a/server-spi-private/src/main/java/org/keycloak/events/Errors.java b/server-spi-private/src/main/java/org/keycloak/events/Errors.java index a32e6a1281..531c7ff6d4 100755 --- a/server-spi-private/src/main/java/org/keycloak/events/Errors.java +++ b/server-spi-private/src/main/java/org/keycloak/events/Errors.java @@ -67,6 +67,8 @@ public interface Errors { String INVALID_INPUT = "invalid_input"; String COOKIE_NOT_FOUND = "cookie_not_found"; + String TOKEN_INTROSPECTION_FAILED = "token_introspection_failed"; + String REGISTRATION_DISABLED = "registration_disabled"; String RESET_CREDENTIAL_DISABLED = "reset_credential_disabled"; diff --git a/server-spi-private/src/main/java/org/keycloak/protocol/oidc/TokenIntrospectionProvider.java b/server-spi-private/src/main/java/org/keycloak/protocol/oidc/TokenIntrospectionProvider.java index 1cd205e666..190ad4d68a 100644 --- a/server-spi-private/src/main/java/org/keycloak/protocol/oidc/TokenIntrospectionProvider.java +++ b/server-spi-private/src/main/java/org/keycloak/protocol/oidc/TokenIntrospectionProvider.java @@ -17,6 +17,7 @@ */ package org.keycloak.protocol.oidc; +import org.keycloak.events.EventBuilder; import org.keycloak.provider.Provider; import jakarta.ws.rs.core.Response; @@ -34,5 +35,5 @@ public interface TokenIntrospectionProvider extends Provider { * @param token the token to introspect. * @return the response with the information about the token */ - Response introspect(String token); + Response introspect(String token, EventBuilder event); } diff --git a/services/src/main/java/org/keycloak/authorization/protection/introspect/RPTIntrospectionProvider.java b/services/src/main/java/org/keycloak/authorization/protection/introspect/RPTIntrospectionProvider.java index 1a538b677d..d3666a281a 100644 --- a/services/src/main/java/org/keycloak/authorization/protection/introspect/RPTIntrospectionProvider.java +++ b/services/src/main/java/org/keycloak/authorization/protection/introspect/RPTIntrospectionProvider.java @@ -28,6 +28,10 @@ import jakarta.ws.rs.core.Response; import com.fasterxml.jackson.annotation.JsonProperty; import com.fasterxml.jackson.databind.node.ObjectNode; import org.jboss.logging.Logger; +import org.keycloak.events.Details; +import org.keycloak.events.Errors; +import org.keycloak.events.EventBuilder; +import org.keycloak.events.EventType; import org.keycloak.models.KeycloakSession; import org.keycloak.protocol.oidc.AccessTokenIntrospectionProvider; import org.keycloak.representations.AccessToken; @@ -49,10 +53,10 @@ public class RPTIntrospectionProvider extends AccessTokenIntrospectionProvider { } @Override - public Response introspect(String token) { + public Response introspect(String token, EventBuilder eventBuilder) { LOGGER.debug("Introspecting requesting party token"); try { - AccessToken accessToken = verifyAccessToken(token); + AccessToken accessToken = verifyAccessToken(token, eventBuilder); ObjectNode tokenMetadata; @@ -85,12 +89,15 @@ public class RPTIntrospectionProvider extends AccessTokenIntrospectionProvider { } } else { tokenMetadata = JsonSerialization.createObjectNode(); + eventBuilder.error(Errors.TOKEN_INTROSPECTION_FAILED); } tokenMetadata.put("active", accessToken != null); return Response.ok(JsonSerialization.writeValueAsBytes(tokenMetadata)).type(MediaType.APPLICATION_JSON_TYPE).build(); } catch (Exception e) { + eventBuilder.detail(Details.REASON, e.getMessage()); + eventBuilder.error(Errors.TOKEN_INTROSPECTION_FAILED); throw new RuntimeException("Error creating token introspection response.", e); } } diff --git a/services/src/main/java/org/keycloak/protocol/oidc/AccessTokenIntrospectionProvider.java b/services/src/main/java/org/keycloak/protocol/oidc/AccessTokenIntrospectionProvider.java index 9bbd01c85c..b7a43d5809 100644 --- a/services/src/main/java/org/keycloak/protocol/oidc/AccessTokenIntrospectionProvider.java +++ b/services/src/main/java/org/keycloak/protocol/oidc/AccessTokenIntrospectionProvider.java @@ -25,6 +25,7 @@ import org.keycloak.common.VerificationException; import org.keycloak.crypto.SignatureProvider; import org.keycloak.crypto.SignatureVerifierContext; import org.keycloak.events.Details; +import org.keycloak.events.Errors; import org.keycloak.events.EventBuilder; import org.keycloak.events.EventType; import org.keycloak.models.AuthenticatedClientSessionModel; @@ -60,9 +61,10 @@ public class AccessTokenIntrospectionProvider implements TokenIntrospectionProvi this.tokenManager = new TokenManager(); } - public Response introspect(String token) { + public Response introspect(String token, EventBuilder eventBuilder) { + AccessToken accessToken = null; try { - AccessToken accessToken = verifyAccessToken(token); + accessToken = verifyAccessToken(token, eventBuilder); accessToken = transformAccessToken(accessToken); ObjectNode tokenMetadata; @@ -105,12 +107,18 @@ public class AccessTokenIntrospectionProvider implements TokenIntrospectionProvi } else { tokenMetadata = JsonSerialization.createObjectNode(); + logger.debug("Keycloak token introspection return false"); + eventBuilder.error(Errors.TOKEN_INTROSPECTION_FAILED); } tokenMetadata.put("active", accessToken != null); return Response.ok(JsonSerialization.writeValueAsBytes(tokenMetadata)).type(MediaType.APPLICATION_JSON_TYPE).build(); } catch (Exception e) { + String clientId = accessToken != null ? accessToken.getIssuedFor() : "unknown"; + logger.debugf(e, "Exception during Keycloak introspection for %s client in realm %s", clientId, realm.getName()); + eventBuilder.detail(Details.REASON, e.getMessage()); + eventBuilder.error(Errors.TOKEN_INTROSPECTION_FAILED); throw new RuntimeException("Error creating token introspection response.", e); } } @@ -166,7 +174,7 @@ public class AccessTokenIntrospectionProvider implements TokenIntrospectionProvi return newToken; } - protected AccessToken verifyAccessToken(String token) { + protected AccessToken verifyAccessToken(String token, EventBuilder eventBuilder) { AccessToken accessToken; try { @@ -178,13 +186,14 @@ public class AccessTokenIntrospectionProvider implements TokenIntrospectionProvi accessToken = verifier.verify().getToken(); } catch (VerificationException e) { - logger.debugf("JWT check failed: %s", e.getMessage()); + logger.debugf("Introspection access token : JWT check failed: %s", e.getMessage()); + eventBuilder.detail(Details.REASON,"Access token JWT check failed"); return null; } RealmModel realm = this.session.getContext().getRealm(); - return tokenManager.checkTokenValidForIntrospection(session, realm, accessToken, false) ? accessToken : null; + return tokenManager.checkTokenValidForIntrospection(session, realm, accessToken, false, eventBuilder) ? accessToken : null; } @Override diff --git a/services/src/main/java/org/keycloak/protocol/oidc/TokenManager.java b/services/src/main/java/org/keycloak/protocol/oidc/TokenManager.java index 9f264a654c..3c26aa1940 100755 --- a/services/src/main/java/org/keycloak/protocol/oidc/TokenManager.java +++ b/services/src/main/java/org/keycloak/protocol/oidc/TokenManager.java @@ -247,9 +247,15 @@ public class TokenManager { * @param updateTimestamps * @return */ - public boolean checkTokenValidForIntrospection(KeycloakSession session, RealmModel realm, AccessToken token, boolean updateTimestamps) { + public boolean checkTokenValidForIntrospection(KeycloakSession session, RealmModel realm, AccessToken token, boolean updateTimestamps, EventBuilder eventBuilder) { ClientModel client = realm.getClientByClientId(token.getIssuedFor()); - if (client == null || !client.isEnabled()) { + if (client == null) { + logger.debugf("Introspection access token : client with clientId %s does not exist", token.getIssuedFor() ); + eventBuilder.detail(Details.REASON, String.format("Could not find client for %s", token.getIssuedFor())); + return false; + } else if (!client.isEnabled()) { + logger.debugf("Introspection access token : client with clientId %s is disabled", token.getIssuedFor() ); + eventBuilder.detail(Details.REASON, String.format("Client with clientId %s is disabled", token.getIssuedFor())); return false; } @@ -258,7 +264,8 @@ public class TokenManager { .withChecks(NotBeforeCheck.forModel(client), TokenVerifier.IS_ACTIVE, new TokenRevocationCheck(session)) .verify(); } catch (VerificationException e) { - logger.debugf("JWT check failed: %s", e.getMessage()); + logger.debugf("Introspection access token for %s client: JWT check failed: %s", token.getIssuedFor(), e.getMessage()); + eventBuilder.detail(Details.REASON, "Introspection access token for "+token.getIssuedFor() +" client: JWT check failed"); return false; } @@ -268,6 +275,8 @@ public class TokenManager { if (token.getSessionState() == null) { UserModel user = lookupUserFromStatelessToken(session, realm, token); valid = isUserValid(session, realm, token, user); + if (!valid) + eventBuilder.detail(Details.REASON, "Could not find valid transient user session"); } else { UserSessionModel userSession = new UserSessionCrossDCManager(session).getUserSessionWithClient(realm, token.getSessionState(), false, client.getId()); @@ -288,14 +297,23 @@ public class TokenManager { } } + if (!valid) { + logger.debugf("Could not find valid user session for session_state = %s", token.getSessionState()); + eventBuilder.detail(Details.REASON, String.format("Could not find valid user session for session_state = %s", token.getSessionState())); + } + if (valid && (token.isIssuedBeforeSessionStart(userSession.getStarted()))) { valid = false; + logger.debugf("Token is issued (%s) before session () has started", String.valueOf(token.getIat()), String.valueOf(userSession.getStarted())); + eventBuilder.detail(Details.REASON, String.format("Token is issued (%s) before user session () has started", String.valueOf(token.getIat()), String.valueOf(userSession.getStarted()))); } AuthenticatedClientSessionModel clientSession = userSession == null ? null : userSession.getAuthenticatedClientSessionByClient(client.getId()); if (clientSession != null) { if (valid && (token.isIssuedBeforeSessionStart(clientSession.getStarted()))) { valid = false; + logger.debugf("Token is issued (%s) before session () has started", String.valueOf(token.getIat()), String.valueOf(clientSession.getStarted())); + eventBuilder.detail(Details.REASON, String.format("Token is issued (%s) before client session () has started", String.valueOf(token.getIat()), String.valueOf(clientSession.getStarted()))); } } @@ -303,7 +321,9 @@ public class TokenManager { if (realm.isRevokeRefreshToken() && (tokenType.equals(TokenUtil.TOKEN_TYPE_REFRESH) || tokenType.equals(TokenUtil.TOKEN_TYPE_OFFLINE)) && !validateTokenReuseForIntrospection(session, realm, token)) { - return false; + logger.debug("Introspection access token for "+token.getIssuedFor() +" client: failed to validate Token reuse for introspection"); + eventBuilder.detail(Details.REASON, "Realm revoke refresh token, token type is "+tokenType+ " and token is not eligible for introspection"); + return false; } if (updateTimestamps && valid) { @@ -313,6 +333,7 @@ public class TokenManager { clientSession.setTimestamp(currentTime); } } + } return valid; @@ -334,15 +355,18 @@ public class TokenManager { validateTokenReuse(session, realm, token, clientSession, false); return true; } catch (OAuthErrorException e) { + logger.debug("validateTokenReuseForIntrospection is false",e); return false; } } private boolean isUserValid(KeycloakSession session, RealmModel realm, AccessToken token, UserModel user) { if (user == null) { + logger.debugf("User does not exist for token introspection"); return false; } if (!user.isEnabled()) { + logger.debugf("User is disable for token introspection"); return false; } try { diff --git a/services/src/main/java/org/keycloak/protocol/oidc/endpoints/TokenIntrospectionEndpoint.java b/services/src/main/java/org/keycloak/protocol/oidc/endpoints/TokenIntrospectionEndpoint.java index c5e59bc0d1..7991e7253d 100755 --- a/services/src/main/java/org/keycloak/protocol/oidc/endpoints/TokenIntrospectionEndpoint.java +++ b/services/src/main/java/org/keycloak/protocol/oidc/endpoints/TokenIntrospectionEndpoint.java @@ -107,7 +107,7 @@ public class TokenIntrospectionEndpoint { try { - Response response = provider.introspect(token); + Response response = provider.introspect(token, event); this.event.success(); diff --git a/services/src/main/java/org/keycloak/services/util/UserSessionUtil.java b/services/src/main/java/org/keycloak/services/util/UserSessionUtil.java index 234bc1f6a8..adcf763835 100644 --- a/services/src/main/java/org/keycloak/services/util/UserSessionUtil.java +++ b/services/src/main/java/org/keycloak/services/util/UserSessionUtil.java @@ -1,5 +1,6 @@ package org.keycloak.services.util; +import org.jboss.logging.Logger; import org.keycloak.common.ClientConnection; import org.keycloak.common.constants.ServiceAccountConstants; import org.keycloak.events.Errors; @@ -11,6 +12,7 @@ import org.keycloak.models.RealmModel; import org.keycloak.models.UserModel; import org.keycloak.models.UserSessionModel; import org.keycloak.models.utils.KeycloakModelUtils; +import org.keycloak.protocol.oidc.AccessTokenIntrospectionProvider; import org.keycloak.protocol.oidc.OIDCLoginProtocol; import org.keycloak.protocol.oidc.TokenManager; import org.keycloak.representations.AccessToken; @@ -24,10 +26,12 @@ import org.keycloak.utils.OAuth2Error; public class UserSessionUtil { + private static final Logger logger = Logger.getLogger(UserSessionUtil.class); + public static UserSessionModel findValidSession(KeycloakSession session, RealmModel realm, AccessToken token, EventBuilder event, ClientModel client) { OAuth2Error error = new OAuth2Error().json(false).realm(realm); if (token.getSessionState() == null) { - return createTransientSessionForClient(session, realm, token, client); + return createTransientSessionForClient(session, realm, token, client, event); } UserSessionModel userSession = new UserSessionCrossDCManager(session).getUserSessionWithClient(realm, token.getSessionState(), false, client.getId()); @@ -46,6 +50,7 @@ public class UserSessionUtil { } if (userSession == null && offlineUserSession == null) { + logger.debug("User session not found or doesn't have client attached on it"); event.error(Errors.USER_SESSION_NOT_FOUND); throw error.invalidToken("User session not found or doesn't have client attached on it"); } @@ -56,15 +61,18 @@ public class UserSessionUtil { event.session(offlineUserSession); } + logger.debug("Session expired"); event.error(Errors.SESSION_EXPIRED); throw error.invalidToken("Session expired"); } - private static UserSessionModel createTransientSessionForClient(KeycloakSession session, RealmModel realm, AccessToken token, ClientModel client) { + private static UserSessionModel createTransientSessionForClient(KeycloakSession session, RealmModel realm, AccessToken token, ClientModel client, EventBuilder event) { OAuth2Error error = new OAuth2Error().json(false).realm(realm); // create a transient session UserModel user = TokenManager.lookupUserFromStatelessToken(session, realm, token); if (user == null) { + logger.debug("Transient User not found"); + event.error(Errors.USER_NOT_FOUND); throw error.invalidToken("User not found"); } ClientConnection clientConnection = session.getContext().getConnection(); @@ -84,12 +92,14 @@ public class UserSessionUtil { private static void checkTokenIssuedAt(RealmModel realm, AccessToken token, UserSessionModel userSession, EventBuilder event, ClientModel client) { OAuth2Error error = new OAuth2Error().json(false).realm(realm); if (token.isIssuedBeforeSessionStart(userSession.getStarted())) { + logger.debug("Stale token for user session"); event.error(Errors.INVALID_TOKEN); throw error.invalidToken("Stale token"); } AuthenticatedClientSessionModel clientSession = userSession.getAuthenticatedClientSessionByClient(client.getId()); if (token.isIssuedBeforeSessionStart(clientSession.getStarted())) { + logger.debug("Stale token for client session"); event.error(Errors.INVALID_TOKEN); throw error.invalidToken("Stale token"); } diff --git a/testsuite/integration-arquillian/tests/base/src/test/java/org/keycloak/testsuite/oauth/ServiceAccountTest.java b/testsuite/integration-arquillian/tests/base/src/test/java/org/keycloak/testsuite/oauth/ServiceAccountTest.java index 1189ea63fb..b077089370 100755 --- a/testsuite/integration-arquillian/tests/base/src/test/java/org/keycloak/testsuite/oauth/ServiceAccountTest.java +++ b/testsuite/integration-arquillian/tests/base/src/test/java/org/keycloak/testsuite/oauth/ServiceAccountTest.java @@ -379,10 +379,11 @@ public class ServiceAccountTest extends AbstractKeycloakTest { // Check that it is not possible to introspect token anymore Assert.assertFalse(getIntrospectionResponse("service-account-cl", "secret1", tokenString)); // TODO: This would be better to be "INTROSPECT_TOKEN_ERROR" - events.expect(EventType.INTROSPECT_TOKEN) + events.expect(EventType.INTROSPECT_TOKEN_ERROR) .client("service-account-cl") .user(is(emptyOrNullString())) .session(is(emptyOrNullString())) + .error(Errors.TOKEN_INTROSPECTION_FAILED) .assertEvent(); }