Enhance error logs and error events during UserInfo endpoint and Token Introspection failure

Closes #24344

Signed-off-by: cgeorgilakis-grnet <cgeorgilakis@admin.grnet.gr>

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";
 

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);
 }

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);
         }
     }

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

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 {

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();
 

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");
         }

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();
     }