From 8ba1266a999b0aeaabdb2bf41bec0d7aa9ded1ac Mon Sep 17 00:00:00 2001
From: Radovan Semancik <radovan.semancik@evolveum.com>
Date: Tue, 30 Jun 2015 11:44:35 +0200
Subject: [PATCH] Improved authorization logging (MID-1858)

---
 .../xml/ns/public/common/common-3.xsd         |   1 +
 .../model/impl/lens/AssignmentEvaluator.java  |   5 +-
 .../role-prop-read-all-modify-some.xml        |   4 +-
 .../test/resources/security/role-readonly.xml |   3 +-
 .../midpoint/security/api/Authorization.java  |  27 +++-
 .../security/impl/SecurityEnforcerImpl.java   | 121 ++++++++++--------
 6 files changed, 99 insertions(+), 62 deletions(-)

diff --git a/infra/schema/src/main/resources/xml/ns/public/common/common-3.xsd b/infra/schema/src/main/resources/xml/ns/public/common/common-3.xsd
index 6d77b796a40..6308bde9bde 100644
--- a/infra/schema/src/main/resources/xml/ns/public/common/common-3.xsd
+++ b/infra/schema/src/main/resources/xml/ns/public/common/common-3.xsd
@@ -6781,6 +6781,7 @@
             </xsd:appinfo>
         </xsd:annotation>
         <xsd:sequence>
+        	<xsd:element name="name" type="xsd:string" minOccurs="0"/>
         	<xsd:element ref="tns:description" minOccurs="0"/>
         	<xsd:element name="decision" minOccurs="0" type="tns:AuthorizationDecisionType" default="allow"/>
         	<xsd:element name="action" type="xsd:anyURI" minOccurs="1" maxOccurs="unbounded">
diff --git a/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/AssignmentEvaluator.java b/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/AssignmentEvaluator.java
index 93256bd8508..57139b124af 100644
--- a/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/AssignmentEvaluator.java
+++ b/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/AssignmentEvaluator.java
@@ -527,7 +527,7 @@ private boolean evaluateAbstractRole(EvaluatedAssignmentImpl<F> assignment, Assi
 			evaluateAssignment(assignment, roleAssignmentPathSegment, evaluateOld, mode, roleType, subSourceDescription, assignmentPath, task, result);
 		}
 		for(AuthorizationType authorizationType: roleType.getAuthorization()) {
-			Authorization authorization = createAuthorization(authorizationType);
+			Authorization authorization = createAuthorization(authorizationType, roleType.toString());
 			assignment.addAuthorization(authorization);
 		}
 		
@@ -574,8 +574,9 @@ public static String dumpAssignment(AssignmentType assignmentType) {
 	}
 
 
-	private Authorization createAuthorization(AuthorizationType authorizationType) {
+	private Authorization createAuthorization(AuthorizationType authorizationType, String sourceDesc) {
 		Authorization authorization = new Authorization(authorizationType);
+		authorization.setSourceDescription(sourceDesc);
 		return authorization;
 	}
 
diff --git a/model/model-intest/src/test/resources/security/role-prop-read-all-modify-some.xml b/model/model-intest/src/test/resources/security/role-prop-read-all-modify-some.xml
index 1e6486abf23..4c7ba7f3ef9 100644
--- a/model/model-intest/src/test/resources/security/role-prop-read-all-modify-some.xml
+++ b/model/model-intest/src/test/resources/security/role-prop-read-all-modify-some.xml
@@ -1,5 +1,5 @@
 <!--
-  ~ Copyright (c) 2014 Evolveum
+  ~ Copyright (c) 2014-2015 Evolveum
   ~
   ~ Licensed under the Apache License, Version 2.0 (the "License");
   ~ you may not use this file except in compliance with the License.
@@ -19,9 +19,11 @@
         xmlns:t="http://prism.evolveum.com/xml/ns/public/types-3">
     <name>Prop Read All Modify Some</name>    
     <authorization>
+    	<name>AUTZreadAllModify1</name>
     	<action>http://midpoint.evolveum.com/xml/ns/public/security/authorization-model-3#read</action>
     </authorization>
     <authorization>
+    	<name>AUTZreadAllModify2</name>
     	<action>http://midpoint.evolveum.com/xml/ns/public/security/authorization-model-3#modify</action>
     	<item>c:fullName</item>
     	<item>c:description</item>
diff --git a/model/model-intest/src/test/resources/security/role-readonly.xml b/model/model-intest/src/test/resources/security/role-readonly.xml
index 17dcf6c1793..64d27b46291 100644
--- a/model/model-intest/src/test/resources/security/role-readonly.xml
+++ b/model/model-intest/src/test/resources/security/role-readonly.xml
@@ -1,5 +1,5 @@
 <!--
-  ~ Copyright (c) 2014 Evolveum
+  ~ Copyright (c) 2014-2015 Evolveum
   ~
   ~ Licensed under the Apache License, Version 2.0 (the "License");
   ~ you may not use this file except in compliance with the License.
@@ -19,6 +19,7 @@
         xmlns:t="http://prism.evolveum.com/xml/ns/public/types-3">
     <name>Read Only</name>    
     <authorization>
+    	<name>AUTZreadonly</name>
     	<action>http://midpoint.evolveum.com/xml/ns/public/security/authorization-model-3#read</action>
     </authorization>
 </role>
diff --git a/repo/security-api/src/main/java/com/evolveum/midpoint/security/api/Authorization.java b/repo/security-api/src/main/java/com/evolveum/midpoint/security/api/Authorization.java
index 3c2bab32134..565a307e77f 100644
--- a/repo/security-api/src/main/java/com/evolveum/midpoint/security/api/Authorization.java
+++ b/repo/security-api/src/main/java/com/evolveum/midpoint/security/api/Authorization.java
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2010-2014 Evolveum
+ * Copyright (c) 2010-2015 Evolveum
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -36,7 +36,8 @@
  */
 public class Authorization implements GrantedAuthority, DebugDumpable {
 	
-	AuthorizationType authorizationType;
+	private AuthorizationType authorizationType;
+	private String sourceDescription;
 
 	public Authorization(AuthorizationType authorizationType) {
 		super();
@@ -56,6 +57,14 @@ public String getDescription() {
 		return authorizationType.getDescription();
 	}
 
+	public String getSourceDescription() {
+		return sourceDescription;
+	}
+
+	public void setSourceDescription(String sourceDescription) {
+		this.sourceDescription = sourceDescription;
+	}
+
 	public AuthorizationDecisionType getDecision() {
 		 AuthorizationDecisionType decision = authorizationType.getDecision();
 		 if (decision == null) {
@@ -84,6 +93,20 @@ public List<OwnedObjectSpecificationType> getTarget() {
 		return authorizationType.getTarget();
 	}
 
+	public String getHumanReadableDesc() {
+		StringBuilder sb = new StringBuilder();
+		if (authorizationType.getName() != null) {
+			sb.append("authorization '").append(authorizationType.getName()).append("'");
+		} else {
+			sb.append("unnamed authorization");
+		}
+		if (sourceDescription != null) {
+			sb.append(" in ");
+			sb.append(sourceDescription);
+		}
+		return sb.toString();
+	}
+	
 	/* (non-Javadoc)
 	 * @see com.evolveum.midpoint.util.DebugDumpable#debugDump()
 	 */
diff --git a/repo/security-impl/src/main/java/com/evolveum/midpoint/security/impl/SecurityEnforcerImpl.java b/repo/security-impl/src/main/java/com/evolveum/midpoint/security/impl/SecurityEnforcerImpl.java
index 418b8ab5f1f..ae3cf6af420 100644
--- a/repo/security-impl/src/main/java/com/evolveum/midpoint/security/impl/SecurityEnforcerImpl.java
+++ b/repo/security-impl/src/main/java/com/evolveum/midpoint/security/impl/SecurityEnforcerImpl.java
@@ -187,43 +187,44 @@ private <O extends ObjectType, T extends ObjectType> boolean isAuthorizedInterna
 			for (GrantedAuthority authority: authorities) {
 				if (authority instanceof Authorization) {
 					Authorization autz = (Authorization)authority;
-					LOGGER.trace("Evaluating authorization {}", autz);
+					String autzHumanReadableDesc = autz.getHumanReadableDesc();
+					LOGGER.trace("Evaluating {}", autzHumanReadableDesc);
 					
 					// First check if the authorization is applicable.
 					
 					// action
 					if (!autz.getAction().contains(operationUrl) && !autz.getAction().contains(AuthorizationConstants.AUTZ_ALL_URL)) {
-						LOGGER.trace("  Authorization not applicable for operation {}", operationUrl);
+						LOGGER.trace("  {} not applicable for operation {}", autzHumanReadableDesc, operationUrl);
 						continue;
 					}
 					
 					// phase
 					if (autz.getPhase() == null) {
-						LOGGER.trace("  Authorization is applicable for all phases (continuing evaluation)");
+						LOGGER.trace("  {} is applicable for all phases (continuing evaluation)", autzHumanReadableDesc);
 					} else {
 						if (autz.getPhase() != phase) {
-							LOGGER.trace("  Authorization is not applicable for phases {} (breaking evaluation)", phase);
+							LOGGER.trace("  {} is not applicable for phases {} (breaking evaluation)", autzHumanReadableDesc, phase);
 							continue;
 						} else {
-							LOGGER.trace("  Authorization is applicable for phases {} (continuing evaluation)", phase);
+							LOGGER.trace("  {} is applicable for phases {} (continuing evaluation)", autzHumanReadableDesc, phase);
 						}
 					}
 					
 					// object
-					if (isApplicable(autz.getObject(), object, midPointPrincipal, ownerResolver, "object")) {
-						LOGGER.trace("  Authorization applicable for object {} (continuing evaluation)", object);
+					if (isApplicable(autz.getObject(), object, midPointPrincipal, ownerResolver, "object", autzHumanReadableDesc)) {
+						LOGGER.trace("  {} applicable for object {} (continuing evaluation)", autzHumanReadableDesc, object);
 					} else {
-						LOGGER.trace("  Authorization not applicable for object {}, none of the object specifications match (breaking evaluation)", 
-								object);
+						LOGGER.trace("  {} not applicable for object {}, none of the object specifications match (breaking evaluation)", 
+								autzHumanReadableDesc, object);
 						continue;
 					}
 					
 					// target
-					if (isApplicable(autz.getTarget(), target, midPointPrincipal, ownerResolver, "target")) {
-						LOGGER.trace("  Authorization applicable for target {} (continuing evaluation)", object);
+					if (isApplicable(autz.getTarget(), target, midPointPrincipal, ownerResolver, "target", autzHumanReadableDesc)) {
+						LOGGER.trace("  {} applicable for target {} (continuing evaluation)", autzHumanReadableDesc, object);
 					} else {
-						LOGGER.trace("  Authorization not applicable for target {}, none of the target specifications match (breaking evaluation)", 
-								object);
+						LOGGER.trace("  {} not applicable for target {}, none of the target specifications match (breaking evaluation)", 
+								autzHumanReadableDesc, object);
 						continue;
 					}
 					
@@ -236,24 +237,24 @@ private <O extends ObjectType, T extends ObjectType> boolean isAuthorizedInterna
 						// attributes. this ended with allow for whole object (MID-2018)
 						Collection<ItemPath> allowed = getItems(autz);
 						if (allow && allowedItems.isEmpty()){
-							LOGGER.trace("  ALLOW operation {} (but continue evaluation)", autz, operationUrl);
+							LOGGER.trace("  {}: ALLOW operation {} (but continue evaluation)", autzHumanReadableDesc, operationUrl);
 						} else if (allow && allowed.isEmpty()){
 							allowedItems.clear();
 						} else {
 							allowedItems.addAll(allowed);
 						}
-						LOGGER.trace("  ALLOW operation {} (but continue evaluation)", autz, operationUrl);
+						LOGGER.trace("  {}: ALLOW operation {} (but continue evaluation)", autzHumanReadableDesc, operationUrl);
 						allow = true;
 						// Do NOT break here. Other authorization statements may still deny the operation
 					} else {
 						// item
 						if (isApplicableItem(autz, object, delta)) {
-							LOGGER.trace("  Deny authorization applicable for items (continuing evaluation)");
+							LOGGER.trace("  {}: Deny authorization applicable for items (continuing evaluation)", autzHumanReadableDesc);
 						} else {
-							LOGGER.trace("  Authorization not applicable for items (breaking evaluation)");
+							LOGGER.trace("  {} not applicable for items (breaking evaluation)", autzHumanReadableDesc);
 							continue;
 						}
-						LOGGER.trace("  DENY operation {}", autz, operationUrl);
+						LOGGER.trace("  {}: DENY operation {}", autzHumanReadableDesc, operationUrl);
 						allow = false;
 						// Break right here. Deny cannot be overridden by allow. This decision cannot be changed. 
 						break;
@@ -342,9 +343,16 @@ public <O extends ObjectType, T extends ObjectType> void authorize(String operat
 		boolean allow = isAuthorized(operationUrl, phase, object, delta, target, ownerResolver);
 		if (!allow) {
 			String username = getQuotedUsername(principal);
-			LOGGER.error("User {} not authorized for operation {}", username, operationUrl);
-			AuthorizationException e = new AuthorizationException("User "+username+" not authorized for operation "
-			+operationUrl);
+			String message;
+			if (target == null && object == null) {
+				message = "User '"+username+"' not authorized for operation "+ operationUrl;
+			} else if (target == null) {
+				message = "User '"+username+"' not authorized for operation "+ operationUrl + " on " + object;
+			} else {
+				message = "User '"+username+"' not authorized for operation "+ operationUrl + " on " + object + " with target " + target;
+			}
+			LOGGER.error("{}", message);
+			AuthorizationException e = new AuthorizationException(message);
 //			+":\n"+((MidPointPrincipal)principal).debugDump());
 			result.recordFatalError(e.getMessage(), e);
 			throw e;
@@ -352,28 +360,28 @@ public <O extends ObjectType, T extends ObjectType> void authorize(String operat
 	}
 	
 	private <O extends ObjectType> boolean isApplicable(List<OwnedObjectSpecificationType> objectSpecTypes, PrismObject<O> object, 
-			MidPointPrincipal midPointPrincipal, OwnerResolver ownerResolver, String desc) throws SchemaException {
+			MidPointPrincipal midPointPrincipal, OwnerResolver ownerResolver, String desc, String autzHumanReadableDesc) throws SchemaException {
 		if (objectSpecTypes != null && !objectSpecTypes.isEmpty()) {
 			if (object == null) {
-				LOGGER.trace("  Authorization not applicable for null "+desc);
+				LOGGER.trace("  {} not applicable for null {}", autzHumanReadableDesc, desc);
 				return false;
 			}
 			for (OwnedObjectSpecificationType autzObject: objectSpecTypes) {
-				if (isApplicable(autzObject, object, midPointPrincipal, ownerResolver, desc)) {
+				if (isApplicable(autzObject, object, midPointPrincipal, ownerResolver, desc, autzHumanReadableDesc)) {
 					return true;
 				}
 			}
 			return false;
 		} else {
-			LOGGER.trace("  No "+desc+" specification in authorization (authorization is applicable)");
+			LOGGER.trace("  {}: No {} specification in authorization (authorization is applicable)", autzHumanReadableDesc, desc);
 			return true;
 		}
 	}
 	
 	private <O extends ObjectType> boolean isApplicable(ObjectSpecificationType objectSpecType, PrismObject<O> object, 
-			MidPointPrincipal principal, OwnerResolver ownerResolver, String desc) throws SchemaException {
+			MidPointPrincipal principal, OwnerResolver ownerResolver, String desc, String autzHumanReadableDesc) throws SchemaException {
 		if (objectSpecType == null) {
-			LOGGER.trace("  Authorization not applicable for {} because of null object specification");
+			LOGGER.trace("  {} not applicable for {} because of null object specification", autzHumanReadableDesc, desc);
 			return false;
 		}
 		SearchFilterType specFilterType = objectSpecType.getFilter();
@@ -383,8 +391,8 @@ private <O extends ObjectType> boolean isApplicable(ObjectSpecificationType obje
 		
 		// Type
 		if (specTypeQName != null && !QNameUtil.match(specTypeQName, objectDefinition.getTypeName())) {
-			LOGGER.trace("  Authorization not applicable for {} because of type mismatch, expected {}, was {}",
-					new Object[]{desc, specTypeQName, objectDefinition.getTypeName()});
+			LOGGER.trace("  {} not applicable for {} because of type mismatch, expected {}, was {}",
+					new Object[]{autzHumanReadableDesc, desc, specTypeQName, objectDefinition.getTypeName()});
 			return false;
 		}
 		
@@ -392,7 +400,7 @@ private <O extends ObjectType> boolean isApplicable(ObjectSpecificationType obje
 		List<SpecialObjectSpecificationType> specSpecial = objectSpecType.getSpecial();
 		if (specSpecial != null && !specSpecial.isEmpty()) {
 			if (specFilterType != null || specOrgRef != null) {
-				throw new SchemaException("Both filter/org and special "+desc+" specification specified in authorization");
+				throw new SchemaException("Both filter/org and special "+desc+" specification specified in "+autzHumanReadableDesc);
 			}
 			for (SpecialObjectSpecificationType special: specSpecial) {
 				if (special == SpecialObjectSpecificationType.SELF) {
@@ -402,36 +410,36 @@ private <O extends ObjectType> boolean isApplicable(ObjectSpecificationType obje
 						// or during initial import. Therefore we are not going to die here. Just ignore it.
 					} else {
 						if (principalOid.equals(object.getOid())) {
-							LOGGER.trace("  'self' authorization applicable for {}", desc);
+							LOGGER.trace("  {}: 'self' authorization applicable for {}", autzHumanReadableDesc, desc);
 							return true;
 						} else {
-							LOGGER.trace("  'self' authorization not applicable for {}, principal OID: {}, {} OID {}",
-									new Object[]{desc, principalOid, desc, object.getOid()});
+							LOGGER.trace("  {}: 'self' authorization not applicable for {}, principal OID: {}, {} OID {}",
+									new Object[]{autzHumanReadableDesc, desc, principalOid, desc, object.getOid()});
 						}
 					}
 				} else {
-					throw new SchemaException("Unsupported special "+desc+" specification specified in authorization: "+special);
+					throw new SchemaException("Unsupported special "+desc+" specification specified in "+autzHumanReadableDesc+": "+special);
 				}
 			}
 			return false;
 		} else {
-			LOGGER.trace("  specials empty: {}", specSpecial);
+			LOGGER.trace("  {}: specials empty: {}", autzHumanReadableDesc, specSpecial);
 		}
 		
 		// Filter
 		if (specFilterType != null) {
 			ObjectFilter specFilter = QueryJaxbConvertor.createObjectFilter(object.getCompileTimeClass(), specFilterType, object.getPrismContext());
 			if (specFilter != null) {
-				ObjectQueryUtil.assertPropertyOnly(specFilter, "Filter in authorization "+desc+" is not property-only filter");
+				ObjectQueryUtil.assertPropertyOnly(specFilter, "Filter in "+autzHumanReadableDesc+" "+desc+" is not property-only filter");
 			}
 			try {
 				if (!ObjectQuery.match(object, specFilter, matchingRuleRegistry)) {
-					LOGGER.trace("  filter authorization not applicable for {}, object OID {}", new Object[] {
-							desc, object.getOid() });
+					LOGGER.trace("  filter {} not applicable for {}, object OID {}", new Object[] {
+							autzHumanReadableDesc, desc, object.getOid() });
 					return false;
 				}
 			} catch (SchemaException ex) {
-				throw new SchemaException("Could not apply authorization for " + object + ". "
+				throw new SchemaException("Could not apply "+autzHumanReadableDesc+" for " + object + ". "
 						+ ex.getMessage(), ex);
 			}
 		}
@@ -447,8 +455,8 @@ private <O extends ObjectType> boolean isApplicable(ObjectSpecificationType obje
 			
 			boolean anySubordinate = repositoryService.isAnySubordinate(specOrgRef.getOid(), objParentOrgOids);
 			if (!anySubordinate) {
-				LOGGER.trace("  org authorization not applicable for {}, object OID {} (autz={} parentRefs={})",
-						new Object[]{desc, object.getOid(), specOrgRef.getOid(), objParentOrgOids});
+				LOGGER.trace("  org {} not applicable for {}, object OID {} (autz={} parentRefs={})",
+						new Object[]{autzHumanReadableDesc, desc, object.getOid(), specOrgRef.getOid(), objParentOrgOids});
 				return false;
 			}			
 		}
@@ -458,34 +466,34 @@ private <O extends ObjectType> boolean isApplicable(ObjectSpecificationType obje
 			ObjectSpecificationType ownerSpec = ((OwnedObjectSpecificationType)objectSpecType).getOwner();
 			if (ownerSpec != null) {
 				if (!object.canRepresent(ShadowType.class)) {
-					LOGGER.trace("  owner object spec not applicable for {}, object OID {} because it is not a shadow",
-							new Object[]{desc, object.getOid()});
+					LOGGER.trace("  {}: owner object spec not applicable for {}, object OID {} because it is not a shadow",
+							new Object[]{autzHumanReadableDesc, desc, object.getOid()});
 					return false;
 				}
 				if (ownerResolver == null) {
 					ownerResolver = userProfileService;
 					if (ownerResolver == null) {
-						LOGGER.trace("  owner object spec not applicable for {}, object OID {} because there is no owner resolver",
-								new Object[]{desc, object.getOid()});
+						LOGGER.trace("  {}: owner object spec not applicable for {}, object OID {} because there is no owner resolver",
+								new Object[]{autzHumanReadableDesc, desc, object.getOid()});
 						return false;
 					}
 				}
 				PrismObject<? extends FocusType> owner = ownerResolver.resolveOwner((PrismObject<ShadowType>)object);
 				if (owner == null) {
-					LOGGER.trace("  owner object spec not applicable for {}, object OID {} because it has no owner",
-							new Object[]{desc, object.getOid()});
+					LOGGER.trace("  {}: owner object spec not applicable for {}, object OID {} because it has no owner",
+							new Object[]{autzHumanReadableDesc, desc, object.getOid()});
 					return false;
 				}
-				boolean ownerApplicable = isApplicable(ownerSpec, owner, principal, ownerResolver, "owner of "+desc);
+				boolean ownerApplicable = isApplicable(ownerSpec, owner, principal, ownerResolver, "owner of "+desc, autzHumanReadableDesc);
 				if (!ownerApplicable) {
-					LOGGER.trace("  owner object spec not applicable for {}, object OID {} because owner does not match (owner={})",
-							new Object[]{desc, object.getOid(), owner});
+					LOGGER.trace("  {}: owner object spec not applicable for {}, object OID {} because owner does not match (owner={})",
+							new Object[]{autzHumanReadableDesc, desc, object.getOid(), owner});
 					return false;
 				}			
 			}
 		}
 
-		LOGGER.trace("  Authorization applicable for {} (filter)", desc);
+		LOGGER.trace("  {} applicable for {} (filter)", autzHumanReadableDesc, desc);
 		return true;
 	}
 	
@@ -660,16 +668,17 @@ public <O extends ObjectType> ObjectSecurityConstraints compileSecurityConstrain
 			for (GrantedAuthority authority: authorities) {
 				if (authority instanceof Authorization) {
 					Authorization autz = (Authorization)authority;
-					LOGGER.trace("Evaluating authorization {}", autz);
+					String autzHumanReadableDesc = autz.getHumanReadableDesc();
+					LOGGER.trace("Evaluating {}", autzHumanReadableDesc);
 					
 					// skip action applicability evaluation. We are interested in all actions
 					
 					// object
-					if (isApplicable(autz.getObject(), object, principal, ownerResolver, "object")) {
-						LOGGER.trace("  Authorization applicable for object {} (continuing evaluation)", object);
+					if (isApplicable(autz.getObject(), object, principal, ownerResolver, "object", autzHumanReadableDesc)) {
+						LOGGER.trace("  {} applicable for object {} (continuing evaluation)", autzHumanReadableDesc, object);
 					} else {
-						LOGGER.trace("  Authorization not applicable for object {}, none of the object specifications match (breaking evaluation)", 
-								object);
+						LOGGER.trace("  {} not applicable for object {}, none of the object specifications match (breaking evaluation)", 
+								autzHumanReadableDesc, object);
 						continue;
 					}