Add logging to the policy providers for general debugging purposes

Signed-off-by: Alice W <105500542+alice-wondered@users.noreply.github.com>
ebariaux · Jan 5, 2024 · cf19c06 · cf19c06
1 parent 2eb31f8
commit cf19c06
Show file tree

Hide file tree

Showing 17 changed files with 72 additions and 7 deletions.
diff --git a/authz/policy/common/pom.xml b/authz/policy/common/pom.xml
@@ -51,6 +51,11 @@
             <artifactId>keycloak-server-spi-private</artifactId>
             <scope>provided</scope>
         </dependency>
+        <dependency>
+            <groupId>org.jboss.logging</groupId>
+            <artifactId>jboss-logging</artifactId>
+            <scope>provided</scope>
+        </dependency>
     </dependencies>
 
 </project>
diff --git a/...n/java/org/keycloak/authorization/policy/provider/aggregated/AggregatePolicyProvider.java b/...n/java/org/keycloak/authorization/policy/provider/aggregated/AggregatePolicyProvider.java
@@ -17,11 +17,10 @@
  */
 package org.keycloak.authorization.policy.provider.aggregated;
 
-import java.util.Collection;
 import java.util.HashMap;
-import java.util.Iterator;
 import java.util.Map;
 
+import org.jboss.logging.Logger;
 import org.keycloak.authorization.AuthorizationProvider;
 import org.keycloak.authorization.Decision;
 import org.keycloak.authorization.model.Policy;
@@ -36,9 +35,11 @@
  * @author <a href="mailto:psilva@redhat.com">Pedro Igor</a>
  */
 public class AggregatePolicyProvider implements PolicyProvider {
+    private static final Logger logger = Logger.getLogger(AggregatePolicyProvider.class);
 
     @Override
     public void evaluate(Evaluation evaluation) {
+        logger.debugv("Aggregate policy {} evaluating using parent class", evaluation.getPolicy().getName());
         DecisionResultCollector decision = new DecisionResultCollector() {
             @Override
             protected void onComplete(Result result) {

diff --git a/...src/main/java/org/keycloak/authorization/policy/provider/client/ClientPolicyProvider.java b/...src/main/java/org/keycloak/authorization/policy/provider/client/ClientPolicyProvider.java
@@ -2,6 +2,7 @@
 
 import java.util.function.BiFunction;
 
+import org.jboss.logging.Logger;
 import org.keycloak.authorization.AuthorizationProvider;
 import org.keycloak.authorization.model.Policy;
 import org.keycloak.authorization.policy.evaluation.Evaluation;
@@ -13,6 +14,7 @@
 
 public class ClientPolicyProvider implements PolicyProvider {
 
+    private static final Logger logger = Logger.getLogger(ClientPolicyProvider.class);
     private final BiFunction<Policy, AuthorizationProvider, ClientPolicyRepresentation> representationFunction;
 
     public ClientPolicyProvider(BiFunction<Policy, AuthorizationProvider, ClientPolicyRepresentation> representationFunction) {
@@ -31,6 +33,7 @@ public void evaluate(Evaluation evaluation) {
 
             if (context.getAttributes().containsValue("kc.client.id", clientModel.getClientId())) {
                 evaluation.grant();
+                logger.debugv("Client policy {} matched with client {} and was granted", evaluation.getPolicy().getName(), clientModel.getClientId());
                 return;
             }
         }

diff --git a/...ava/org/keycloak/authorization/policy/provider/clientscope/ClientScopePolicyProvider.java b/...ava/org/keycloak/authorization/policy/provider/clientscope/ClientScopePolicyProvider.java
@@ -20,6 +20,7 @@
 import java.util.Set;
 import java.util.function.BiFunction;
 
+import org.jboss.logging.Logger;
 import org.keycloak.authorization.AuthorizationProvider;
 import org.keycloak.authorization.identity.Identity;
 import org.keycloak.authorization.model.Policy;
@@ -34,6 +35,7 @@
  */
 public class ClientScopePolicyProvider implements PolicyProvider {
 
+    private static final Logger logger = Logger.getLogger(ClientScopePolicyProvider.class);
     private final BiFunction<Policy, AuthorizationProvider, ClientScopePolicyRepresentation> representationFunction;
 
     public ClientScopePolicyProvider(
@@ -68,6 +70,7 @@ public void evaluate(Evaluation evaluation) {
                 }
             }
         }
+        logger.debugv("Client Scope Policy {} evaluated to {}", policy.getName(), evaluation.getEffect());
     }
 
     private boolean hasClientScope(Identity identity, ClientScopeModel clientScope) {

diff --git a/...n/src/main/java/org/keycloak/authorization/policy/provider/group/GroupPolicyProvider.java b/...n/src/main/java/org/keycloak/authorization/policy/provider/group/GroupPolicyProvider.java
@@ -21,6 +21,7 @@
 import java.util.List;
 import java.util.function.BiFunction;
 
+import org.jboss.logging.Logger;
 import org.keycloak.authorization.AuthorizationProvider;
 import org.keycloak.authorization.attribute.Attributes;
 import org.keycloak.authorization.attribute.Attributes.Entry;
@@ -36,6 +37,7 @@
  */
 public class GroupPolicyProvider implements PolicyProvider {
 
+    private static final Logger logger = Logger.getLogger(GroupPolicyProvider.class);
     private final BiFunction<Policy, AuthorizationProvider, GroupPolicyRepresentation> representationFunction;
 
     public GroupPolicyProvider(BiFunction<Policy, AuthorizationProvider, GroupPolicyRepresentation> representationFunction) {
@@ -75,6 +77,7 @@ public void evaluate(Evaluation evaluation) {
                 }
             }
         }
+        logger.debugv("Groups policy {} evaluated to {} with identity groups {}", policy.getName(), evaluation.getEffect(), groupsClaim);
     }
 
     @Override

diff --git a/.../common/src/main/java/org/keycloak/authorization/policy/provider/js/JSPolicyProvider.java b/.../common/src/main/java/org/keycloak/authorization/policy/provider/js/JSPolicyProvider.java
@@ -22,6 +22,7 @@
 import javax.script.ScriptContext;
 import javax.script.SimpleScriptContext;
 
+import org.jboss.logging.Logger;
 import org.keycloak.authorization.AuthorizationProvider;
 import org.keycloak.authorization.model.Policy;
 import org.keycloak.authorization.policy.evaluation.Evaluation;
@@ -33,6 +34,8 @@
  */
 class JSPolicyProvider implements PolicyProvider {
 
+    private static final Logger logger = Logger.getLogger(JSPolicyProvider.class);
+
     private final BiFunction<AuthorizationProvider, Policy, EvaluatableScriptAdapter> evaluatableScript;
 
     JSPolicyProvider(final BiFunction<AuthorizationProvider, Policy, EvaluatableScriptAdapter> evaluatableScript) {
@@ -51,6 +54,7 @@ public void evaluate(Evaluation evaluation) {
             context.setAttribute("$evaluation", evaluation, ScriptContext.ENGINE_SCOPE);
 
             adapter.eval(context);
+            logger.debugv("JS Policy {} evaluated to status {}", policy.getName(), evaluation.getEffect());
         }
         catch (Exception e) {
             throw new RuntimeException("Error evaluating JS Policy [" + policy.getName() + "].", e);

diff --git a/.../src/main/java/org/keycloak/authorization/policy/provider/js/JSPolicyProviderFactory.java b/.../src/main/java/org/keycloak/authorization/policy/provider/js/JSPolicyProviderFactory.java
@@ -5,7 +5,6 @@
 import org.keycloak.authorization.model.Policy;
 import org.keycloak.authorization.policy.provider.PolicyProvider;
 import org.keycloak.authorization.policy.provider.PolicyProviderFactory;
-import org.keycloak.common.Profile;
 import org.keycloak.models.KeycloakSession;
 import org.keycloak.models.KeycloakSessionFactory;
 import org.keycloak.models.RealmModel;

diff --git a/...ava/org/keycloak/authorization/policy/provider/permission/AbstractPermissionProvider.java b/...ava/org/keycloak/authorization/policy/provider/permission/AbstractPermissionProvider.java
@@ -16,8 +16,12 @@
  */
 package org.keycloak.authorization.policy.provider.permission;
 
+import java.util.HashSet;
+import java.util.Set;
+import org.jboss.logging.Logger;
 import org.keycloak.authorization.AuthorizationProvider;
 import org.keycloak.authorization.Decision;
+import org.keycloak.authorization.Decision.Effect;
 import org.keycloak.authorization.model.Policy;
 import org.keycloak.authorization.permission.ResourcePermission;
 import org.keycloak.authorization.policy.evaluation.DefaultEvaluation;
@@ -32,6 +36,8 @@
  */
 public abstract class AbstractPermissionProvider implements PolicyProvider {
 
+    private static final Logger logger = Logger.getLogger(AbstractPermissionProvider.class);
+
     @Override
     public void evaluate(Evaluation evaluation) {
         AuthorizationProvider authorization = evaluation.getAuthorizationProvider();
@@ -60,6 +66,7 @@ public void evaluate(Evaluation evaluation) {
                 defaultEvaluation.setEffect(effect);
             }
         }
+        logger.debugv("Policy {} was evaluated with status {} in {} mode after processing {} associated policies: {}", policy.getName(), evaluation.getEffect(), policy.getDecisionStrategy(), policy.getAssociatedPolicies().size(), policy.getAssociatedPolicies());
     }
 
     @Override

diff --git a/...in/java/org/keycloak/authorization/policy/provider/permission/ResourcePolicyProvider.java b/...in/java/org/keycloak/authorization/policy/provider/permission/ResourcePolicyProvider.java
@@ -16,6 +16,7 @@
  */
 package org.keycloak.authorization.policy.provider.permission;
 
+import org.jboss.logging.Logger;
 import org.keycloak.authorization.Decision;
 import org.keycloak.authorization.model.Policy;
 import org.keycloak.authorization.permission.ResourcePermission;
@@ -30,8 +31,11 @@
  */
 public class ResourcePolicyProvider extends AbstractPermissionProvider {
 
+    private static final Logger logger = Logger.getLogger(ResourcePolicyProvider.class);
+
     @Override
     public void evaluate(Evaluation evaluation) {
+        logger.debugv("Resource policy {} evaluating using parent class", evaluation.getPolicy().getName());
         DefaultEvaluation defaultEvaluation = DefaultEvaluation.class.cast(evaluation);
         Map<Policy, Map<Object, Decision.Effect>> decisionCache = defaultEvaluation.getDecisionCache();
         Policy policy = defaultEvaluation.getParentPolicy();
@@ -43,7 +47,6 @@ public void evaluate(Evaluation evaluation) {
             defaultEvaluation.setEffect(effect);
             return;
         }
-
         super.evaluate(evaluation);
 
         decisions.put(permission.getResource(), defaultEvaluation.getEffect());

diff --git a/.../main/java/org/keycloak/authorization/policy/provider/permission/ScopePolicyProvider.java b/.../main/java/org/keycloak/authorization/policy/provider/permission/ScopePolicyProvider.java
@@ -16,9 +16,9 @@
  */
 package org.keycloak.authorization.policy.provider.permission;
 
+import org.jboss.logging.Logger;
 import org.keycloak.authorization.Decision;
 import org.keycloak.authorization.model.Policy;
-import org.keycloak.authorization.model.Scope;
 import org.keycloak.authorization.permission.ResourcePermission;
 import org.keycloak.authorization.policy.evaluation.DefaultEvaluation;
 import org.keycloak.authorization.policy.evaluation.Evaluation;
@@ -31,8 +31,11 @@
  */
 public class ScopePolicyProvider extends AbstractPermissionProvider {
 
+    private static final Logger logger = Logger.getLogger(ScopePolicyProvider.class);
+
     @Override
     public void evaluate(Evaluation evaluation) {
+        logger.debugv("Scope policy {} evaluating using parent class", evaluation.getPolicy().getName());
         DefaultEvaluation defaultEvaluation = DefaultEvaluation.class.cast(evaluation);
         Map<Policy, Map<Object, Decision.Effect>> decisionCache = defaultEvaluation.getDecisionCache();
         Policy policy = defaultEvaluation.getParentPolicy();

diff --git a/...rc/main/java/org/keycloak/authorization/policy/provider/permission/UMAPolicyProvider.java b/...rc/main/java/org/keycloak/authorization/policy/provider/permission/UMAPolicyProvider.java
@@ -16,6 +16,7 @@
  */
 package org.keycloak.authorization.policy.provider.permission;
 
+import org.jboss.logging.Logger;
 import org.keycloak.authorization.identity.Identity;
 import org.keycloak.authorization.model.Resource;
 import org.keycloak.authorization.permission.ResourcePermission;
@@ -26,8 +27,11 @@
  */
 public class UMAPolicyProvider extends AbstractPermissionProvider {
 
+    private static final Logger logger = Logger.getLogger(UMAPolicyProvider.class);
+
     @Override
     public void evaluate(Evaluation evaluation) {
+        logger.debugv("UMA policy {} evaluating using parent class", evaluation.getPolicy().getName());
         ResourcePermission permission = evaluation.getPermission();
         Resource resource = permission.getResource();
 
@@ -36,6 +40,7 @@ public void evaluate(Evaluation evaluation) {
 
             // no need to evaluate UMA permissions to resource owner resources
             if (resource.getOwner().equals(identity.getId())) {
+                logger.debugv("UMA resource is owned by the current user, bypassing evaluation");
                 evaluation.grant();
                 return;
             }

diff --git a/...n/src/main/java/org/keycloak/authorization/policy/provider/regex/RegexPolicyProvider.java b/...n/src/main/java/org/keycloak/authorization/policy/provider/regex/RegexPolicyProvider.java
@@ -28,6 +28,7 @@
 import java.util.regex.Matcher;
 import java.util.regex.Pattern;
 
+import org.jboss.logging.Logger;
 import org.keycloak.authorization.AuthorizationProvider;
 import org.keycloak.authorization.attribute.Attributes;
 import org.keycloak.authorization.model.Policy;
@@ -42,6 +43,7 @@
  */
 public class RegexPolicyProvider implements PolicyProvider {
 
+    private static final Logger logger = Logger.getLogger(RegexPolicyProvider.class);
     private final BiFunction<Policy, AuthorizationProvider, RegexPolicyRepresentation> representationFunction;
 
     public RegexPolicyProvider(BiFunction<Policy, AuthorizationProvider, RegexPolicyRepresentation> representationFunction) {
@@ -66,6 +68,7 @@ public void evaluate(Evaluation evaluation) {
         Matcher matcher = pattern.matcher(value);
         if (matcher.matches()) {
             evaluation.grant();
+            logger.debugv("policy {} evaluated with status {} on identity {} and claim value {}", policy.getName(), evaluation.getEffect(), evaluation.getContext().getIdentity().getId(), getClaimValue(evaluation, policy));
         }
     }
 

diff --git a/...mon/src/main/java/org/keycloak/authorization/policy/provider/role/RolePolicyProvider.java b/...mon/src/main/java/org/keycloak/authorization/policy/provider/role/RolePolicyProvider.java
@@ -20,6 +20,7 @@
 import java.util.Set;
 import java.util.function.BiFunction;
 
+import org.jboss.logging.Logger;
 import org.keycloak.authorization.AuthorizationProvider;
 import org.keycloak.authorization.identity.Identity;
 import org.keycloak.authorization.model.Policy;
@@ -37,6 +38,8 @@ public class RolePolicyProvider implements PolicyProvider {
 
     private final BiFunction<Policy, AuthorizationProvider, RolePolicyRepresentation> representationFunction;
 
+    private static final Logger logger = Logger.getLogger(RolePolicyProvider.class);
+
     public RolePolicyProvider(BiFunction<Policy, AuthorizationProvider, RolePolicyRepresentation> representationFunction) {
         this.representationFunction = representationFunction;
     }
@@ -63,6 +66,7 @@ public void evaluate(Evaluation evaluation) {
                 }
             }
         }
+        logger.debugv("policy {} evaluated with status {} on identity {}", policy.getName(), evaluation.getEffect(), identity.getId());
     }
 
     private boolean hasRole(Identity identity, RoleModel role, RealmModel realm) {

diff --git a/...mon/src/main/java/org/keycloak/authorization/policy/provider/time/TimePolicyProvider.java b/...mon/src/main/java/org/keycloak/authorization/policy/provider/time/TimePolicyProvider.java
@@ -21,6 +21,7 @@
 import java.util.Calendar;
 import java.util.Date;
 
+import org.jboss.logging.Logger;
 import org.keycloak.authorization.attribute.Attributes;
 import org.keycloak.authorization.model.Policy;
 import org.keycloak.authorization.policy.evaluation.Evaluation;
@@ -32,6 +33,8 @@
  */
 public class TimePolicyProvider implements PolicyProvider {
 
+    private static final Logger logger = Logger.getLogger(TimePolicyProvider.class);
+
     static String DEFAULT_DATE_PATTERN = "yyyy-MM-dd HH:mm:ss";
 
     static String CONTEXT_TIME_ENTRY = "kc.time.date_time";
@@ -40,6 +43,7 @@ public class TimePolicyProvider implements PolicyProvider {
     public void evaluate(Evaluation evaluation) {
         Policy policy = evaluation.getPolicy();
         SimpleDateFormat dateFormat = new SimpleDateFormat(DEFAULT_DATE_PATTERN);
+        logger.debugv("Time policy {} evaluating", policy.getName());
         try {
             String contextTime = null;
             EvaluationContext context = evaluation.getContext();
@@ -54,6 +58,7 @@ public void evaluate(Evaluation evaluation) {
             String notBefore = policy.getConfig().get("nbf");
             if (notBefore != null && !"".equals(notBefore)) {
                 if (actualDate.before(dateFormat.parse(format(notBefore)))) {
+                    logger.debugv("Provided date is before the accepted date: (nbf) ", notBefore);
                     evaluation.deny();
                     return;
                 }
@@ -62,6 +67,7 @@ public void evaluate(Evaluation evaluation) {
             String notOnOrAfter = policy.getConfig().get("noa");
             if (notOnOrAfter != null && !"".equals(notOnOrAfter)) {
                 if (actualDate.after(dateFormat.parse(format(notOnOrAfter)))) {
+                    logger.debugv("Provided date is after the accepted date: (noa) {}", notOnOrAfter);
                     evaluation.deny();
                     return;
                 }
@@ -72,6 +78,7 @@ public void evaluate(Evaluation evaluation) {
                     || isInvalid(actualDate, Calendar.YEAR, "year", policy)
                     || isInvalid(actualDate, Calendar.HOUR_OF_DAY, "hour", policy)
                     || isInvalid(actualDate, Calendar.MINUTE, "minute", policy)) {
+                logger.debugv("Invalid date provided to time policy {}", policy.getName());
                 evaluation.deny();
                 return;
             }

diff --git a/...mon/src/main/java/org/keycloak/authorization/policy/provider/user/UserPolicyProvider.java b/...mon/src/main/java/org/keycloak/authorization/policy/provider/user/UserPolicyProvider.java
@@ -18,8 +18,8 @@
 package org.keycloak.authorization.policy.provider.user;
 
 import java.util.function.BiFunction;
-import java.util.function.Function;
 
+import org.jboss.logging.Logger;
 import org.keycloak.authorization.AuthorizationProvider;
 import org.keycloak.authorization.model.Policy;
 import org.keycloak.authorization.policy.evaluation.Evaluation;
@@ -32,6 +32,8 @@
  */
 public class UserPolicyProvider implements PolicyProvider {
 
+    private static final Logger logger = Logger.getLogger(UserPolicyProvider.class);
+
     private final BiFunction<Policy, AuthorizationProvider, UserPolicyRepresentation> representationFunction;
 
     public UserPolicyProvider(BiFunction<Policy, AuthorizationProvider, UserPolicyRepresentation> representationFunction) {
@@ -49,6 +51,7 @@ public void evaluate(Evaluation evaluation) {
                 break;
             }
         }
+        logger.debugv("User policy {} evaluated to status {} on identity {} with accepted users: {}", evaluation.getPolicy().getName(), evaluation.getEffect(), evaluation.getContext().getIdentity().getId(), representation.getUsers());
     }
 
     @Override