RANGER-794: commit id f79bc59a0b4756ca5195a2ffb30759b4a82175ef Signed-off-by: Madhan Neethiraj <[email protected]>
Project: http://git-wip-us.apache.org/repos/asf/incubator-ranger/repo Commit: http://git-wip-us.apache.org/repos/asf/incubator-ranger/commit/bec2fefe Tree: http://git-wip-us.apache.org/repos/asf/incubator-ranger/tree/bec2fefe Diff: http://git-wip-us.apache.org/repos/asf/incubator-ranger/diff/bec2fefe Branch: refs/heads/ranger-0.5 Commit: bec2fefe1b0101a2be17e57ab3ecfeeb91837bde Parents: e72cb20 Author: Abhay Kulkarni <[email protected]> Authored: Wed Jan 13 11:56:04 2016 -0800 Committer: Madhan Neethiraj <[email protected]> Committed: Sun Mar 20 10:34:39 2016 -0700 ---------------------------------------------------------------------- .../policyengine/RangerPolicyEngineImpl.java | 61 +++++++++++++++++- .../policyengine/RangerPolicyRepository.java | 12 ++++ .../RangerCachedPolicyEvaluator.java | 2 +- .../RangerDefaultPolicyEvaluator.java | 65 ++++++++++++++++---- .../RangerDefaultPolicyItemEvaluator.java | 50 ++++++++++++++- .../ranger/plugin/util/PolicyRefresher.java | 12 +++- .../ranger/plugin/util/RangerPerfTracer.java | 9 ++- ranger-tools/conf/log4j.properties | 4 +- .../src/test/resources/log4j.properties | 4 +- ranger-tools/testdata/test_modules.txt | 18 +++++- 10 files changed, 210 insertions(+), 27 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/incubator-ranger/blob/bec2fefe/agents-common/src/main/java/org/apache/ranger/plugin/policyengine/RangerPolicyEngineImpl.java ---------------------------------------------------------------------- diff --git a/agents-common/src/main/java/org/apache/ranger/plugin/policyengine/RangerPolicyEngineImpl.java b/agents-common/src/main/java/org/apache/ranger/plugin/policyengine/RangerPolicyEngineImpl.java index d2b3a5c..c276d5a 100644 --- a/agents-common/src/main/java/org/apache/ranger/plugin/policyengine/RangerPolicyEngineImpl.java +++ b/agents-common/src/main/java/org/apache/ranger/plugin/policyengine/RangerPolicyEngineImpl.java @@ -27,6 +27,7 @@ import org.apache.ranger.plugin.model.RangerPolicy; import org.apache.ranger.plugin.model.RangerServiceDef; import org.apache.ranger.plugin.model.RangerPolicy.RangerPolicyResource; import org.apache.ranger.plugin.policyevaluator.RangerPolicyEvaluator; +import org.apache.ranger.plugin.util.RangerPerfTracer; import org.apache.ranger.plugin.util.ServicePolicies; import java.util.ArrayList; @@ -39,6 +40,11 @@ import java.util.Set; public class RangerPolicyEngineImpl implements RangerPolicyEngine { private static final Log LOG = LogFactory.getLog(RangerPolicyEngineImpl.class); + private static final Log PERF_POLICYENGINE_INIT_LOG = RangerPerfTracer.getPerfLogger("policyengine.init"); + private static final Log PERF_POLICYENGINE_REQUEST_LOG = RangerPerfTracer.getPerfLogger("policyengine.request"); + private static final Log PERF_POLICYENGINE_AUDIT_LOG = RangerPerfTracer.getPerfLogger("policyengine.audit"); + private static final Log PERF_CONTEXTENRICHER_REQUEST_LOG = RangerPerfTracer.getPerfLogger("contextenricher.request"); + private final RangerPolicyRepository policyRepository; @@ -51,12 +57,20 @@ public class RangerPolicyEngineImpl implements RangerPolicyEngine { LOG.debug("==> RangerPolicyEngineImpl(" + servicePolicies + ", " + options + ")"); } + RangerPerfTracer perf = null; + + if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICYENGINE_INIT_LOG)) { + perf = RangerPerfTracer.getPerfTracer(PERF_POLICYENGINE_INIT_LOG, "RangerPolicyEngine.init(hashCode=" + Integer.toHexString(System.identityHashCode(this)) + ")"); + } + if(options == null) { options = new RangerPolicyEngineOptions(); } policyRepository = new RangerPolicyRepository(servicePolicies, options); + RangerPerfTracer.log(perf); + if(LOG.isDebugEnabled()) { LOG.debug("<== RangerPolicyEngineImpl()"); } @@ -93,9 +107,20 @@ public class RangerPolicyEngineImpl implements RangerPolicyEngine { List<RangerContextEnricher> enrichers = policyRepository.getContextEnrichers(); if(!CollectionUtils.isEmpty(enrichers)) { + for(RangerContextEnricher enricher : enrichers) { + + RangerPerfTracer perf = null; + + if(RangerPerfTracer.isPerfTraceEnabled(PERF_CONTEXTENRICHER_REQUEST_LOG)) { + perf = RangerPerfTracer.getPerfTracer(PERF_CONTEXTENRICHER_REQUEST_LOG, "RangerContextEnricher.enrich(requestHashCode=" + Integer.toHexString(System.identityHashCode(request)) + ")"); + } + enricher.enrich(request); + + RangerPerfTracer.log(perf); } + } if(LOG.isDebugEnabled()) { @@ -136,12 +161,28 @@ public class RangerPolicyEngineImpl implements RangerPolicyEngine { LOG.debug("==> RangerPolicyEngineImpl.isAccessAllowed(" + request + ")"); } + RangerPerfTracer perf = null; + + if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICYENGINE_REQUEST_LOG)) { + perf = RangerPerfTracer.getPerfTracer(PERF_POLICYENGINE_REQUEST_LOG, "RangerPolicyEngine.isAccessAllowed(requestHashCode=" + Integer.toHexString(System.identityHashCode(request)) + ")"); + } + RangerAccessResult ret = isAccessAllowedNoAudit(request); - if(resultProcessor != null) { + if (resultProcessor != null) { + + RangerPerfTracer perfAuditTracer = null; + if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICYENGINE_AUDIT_LOG)) { + perfAuditTracer = RangerPerfTracer.getPerfTracer(PERF_POLICYENGINE_AUDIT_LOG, "RangerPolicyEngine.processAudit(requestHashCode=" + Integer.toHexString(System.identityHashCode(request)) + ")"); + } + resultProcessor.processResult(ret); + + RangerPerfTracer.log(perfAuditTracer); } + RangerPerfTracer.log(perf); + if(LOG.isDebugEnabled()) { LOG.debug("<== RangerPolicyEngineImpl.isAccessAllowed(" + request + "): " + ret); } @@ -182,6 +223,11 @@ public class RangerPolicyEngineImpl implements RangerPolicyEngine { LOG.debug("==> RangerPolicyEngineImpl.isAccessAllowed(" + resource + ", " + user + ", " + userGroups + ", " + accessType + ")"); } + RangerPerfTracer perf = null; + + if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICYENGINE_REQUEST_LOG)) { + perf = RangerPerfTracer.getPerfTracer(PERF_POLICYENGINE_REQUEST_LOG, "RangerPolicyEngine.isAccessAllowed(user=" + user + ",accessType=" + accessType + "resource=" + resource.getAsString() + ")"); + } boolean ret = false; for(RangerPolicyEvaluator evaluator : policyRepository.getPolicyEvaluators()) { @@ -192,6 +238,8 @@ public class RangerPolicyEngineImpl implements RangerPolicyEngine { } } + RangerPerfTracer.log(perf); + if(LOG.isDebugEnabled()) { LOG.debug("<== RangerPolicyEngineImpl.isAccessAllowed(" + resource + ", " + user + ", " + userGroups + ", " + accessType + "): " + ret); } @@ -206,6 +254,11 @@ public class RangerPolicyEngineImpl implements RangerPolicyEngine { LOG.debug("==> RangerPolicyEngineImpl.isAccessAllowed(" + resources + ", " + user + ", " + userGroups + ", " + accessType + ")"); } + RangerPerfTracer perf = null; + + if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICYENGINE_REQUEST_LOG)) { + perf = RangerPerfTracer.getPerfTracer(PERF_POLICYENGINE_REQUEST_LOG, "RangerPolicyEngine.isAccessAllowed(user=" + user + ",accessType=" + accessType + ")"); + } boolean ret = false; for(RangerPolicyEvaluator evaluator : policyRepository.getPolicyEvaluators()) { @@ -216,7 +269,9 @@ public class RangerPolicyEngineImpl implements RangerPolicyEngine { } } - if(LOG.isDebugEnabled()) { + RangerPerfTracer.log(perf); + + if (LOG.isDebugEnabled()) { LOG.debug("<== RangerPolicyEngineImpl.isAccessAllowed(" + resources + ", " + user + ", " + userGroups + ", " + accessType + "): " + ret); } @@ -300,7 +355,7 @@ public class RangerPolicyEngineImpl implements RangerPolicyEngine { } } - if(LOG.isDebugEnabled()) { + if (LOG.isDebugEnabled()) { LOG.debug("<== RangerPolicyEngineImpl.isAccessAllowedNoAudit(" + request + "): " + ret); } http://git-wip-us.apache.org/repos/asf/incubator-ranger/blob/bec2fefe/agents-common/src/main/java/org/apache/ranger/plugin/policyengine/RangerPolicyRepository.java ---------------------------------------------------------------------- diff --git a/agents-common/src/main/java/org/apache/ranger/plugin/policyengine/RangerPolicyRepository.java b/agents-common/src/main/java/org/apache/ranger/plugin/policyengine/RangerPolicyRepository.java index 45bc792..1f422c5 100644 --- a/agents-common/src/main/java/org/apache/ranger/plugin/policyengine/RangerPolicyRepository.java +++ b/agents-common/src/main/java/org/apache/ranger/plugin/policyengine/RangerPolicyRepository.java @@ -31,6 +31,7 @@ import org.apache.ranger.plugin.policyevaluator.RangerCachedPolicyEvaluator; import org.apache.ranger.plugin.policyevaluator.RangerDefaultPolicyEvaluator; import org.apache.ranger.plugin.policyevaluator.RangerOptimizedPolicyEvaluator; import org.apache.ranger.plugin.policyevaluator.RangerPolicyEvaluator; +import org.apache.ranger.plugin.util.RangerPerfTracer; import org.apache.ranger.plugin.util.ServicePolicies; import java.util.ArrayList; @@ -42,6 +43,8 @@ import java.util.Map; public class RangerPolicyRepository { private static final Log LOG = LogFactory.getLog(RangerPolicyRepository.class); + private static final Log PERF_CONTEXTENRICHER_INIT_LOG = RangerPerfTracer.getPerfLogger("contextenricher.init"); + private final String serviceName; private final RangerServiceDef serviceDef; private final List<RangerPolicy> policies; @@ -84,6 +87,7 @@ public class RangerPolicyRepository { RangerPolicyEvaluator evaluator = buildPolicyEvaluator(policy, serviceDef, options); + if (evaluator != null) { policyEvaluators.add(evaluator); } @@ -133,6 +137,12 @@ public class RangerPolicyRepository { RangerContextEnricher ret = null; + RangerPerfTracer perf = null; + + if(RangerPerfTracer.isPerfTraceEnabled(PERF_CONTEXTENRICHER_INIT_LOG)) { + perf = RangerPerfTracer.getPerfTracer(PERF_CONTEXTENRICHER_INIT_LOG, "RangerContextEnricher.init(name=" + enricherDef.getName() + ")"); + } + String name = enricherDef != null ? enricherDef.getName() : null; String clsName = enricherDef != null ? enricherDef.getEnricher() : null; @@ -152,6 +162,8 @@ public class RangerPolicyRepository { ret.init(); } + RangerPerfTracer.log(perf); + if(LOG.isDebugEnabled()) { LOG.debug("<== RangerPolicyRepository.buildContextEnricher(" + enricherDef + "): " + ret); } http://git-wip-us.apache.org/repos/asf/incubator-ranger/blob/bec2fefe/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerCachedPolicyEvaluator.java ---------------------------------------------------------------------- diff --git a/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerCachedPolicyEvaluator.java b/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerCachedPolicyEvaluator.java index d67777c..91a53d8 100644 --- a/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerCachedPolicyEvaluator.java +++ b/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerCachedPolicyEvaluator.java @@ -40,7 +40,7 @@ public class RangerCachedPolicyEvaluator extends RangerOptimizedPolicyEvaluator super.init(policy, serviceDef, options); cache = RangerResourceAccessCacheImpl.getInstance(serviceDef, policy); - + if(LOG.isDebugEnabled()) { LOG.debug("<== RangerCachedPolicyEvaluator.init()"); } http://git-wip-us.apache.org/repos/asf/incubator-ranger/blob/bec2fefe/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerDefaultPolicyEvaluator.java ---------------------------------------------------------------------- diff --git a/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerDefaultPolicyEvaluator.java b/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerDefaultPolicyEvaluator.java index 9f60b7b..d570c6c 100644 --- a/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerDefaultPolicyEvaluator.java +++ b/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerDefaultPolicyEvaluator.java @@ -44,14 +44,19 @@ import org.apache.ranger.plugin.policyengine.RangerAccessResult; import org.apache.ranger.plugin.policyengine.RangerPolicyEngineOptions; import org.apache.ranger.plugin.policyresourcematcher.RangerDefaultPolicyResourceMatcher; import org.apache.ranger.plugin.policyresourcematcher.RangerPolicyResourceMatcher; +import org.apache.ranger.plugin.util.RangerPerfTracer; public class RangerDefaultPolicyEvaluator extends RangerAbstractPolicyEvaluator { private static final Log LOG = LogFactory.getLog(RangerDefaultPolicyEvaluator.class); + private static final Log PERF_POLICY_INIT_LOG = RangerPerfTracer.getPerfLogger("policy.init"); + private static final Log PERF_POLICY_REQUEST_LOG = RangerPerfTracer.getPerfLogger("policy.request"); + private RangerPolicyResourceMatcher resourceMatcher = null; private List<RangerPolicyItemEvaluator> policyItemEvaluators = null; private int customConditionsCount = 0; + private String perfTag; @Override public int getCustomConditionsCount() { @@ -65,6 +70,18 @@ public class RangerDefaultPolicyEvaluator extends RangerAbstractPolicyEvaluator } preprocessPolicy(policy, serviceDef); + StringBuffer perfTagBuffer = new StringBuffer(); + if (policy != null) { + perfTagBuffer.append("policyId=").append(policy.getId()).append(", policyName=").append(policy.getName()); + } + + perfTag = perfTagBuffer.toString(); + + RangerPerfTracer perf = null; + + if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICY_INIT_LOG)) { + perf = RangerPerfTracer.getPerfTracer(PERF_POLICY_INIT_LOG, "RangerPolicyEvaluator.init(" + perfTag + ")"); + } super.init(policy, serviceDef, options); @@ -92,6 +109,8 @@ public class RangerDefaultPolicyEvaluator extends RangerAbstractPolicyEvaluator policyItemEvaluators = Collections.<RangerPolicyItemEvaluator>emptyList(); } + RangerPerfTracer.log(perf); + if(LOG.isDebugEnabled()) { LOG.debug("<== RangerDefaultPolicyEvaluator.init()"); } @@ -103,6 +122,13 @@ public class RangerDefaultPolicyEvaluator extends RangerAbstractPolicyEvaluator LOG.debug("==> RangerDefaultPolicyEvaluator.evaluate(" + request + ", " + result + ")"); } + RangerPerfTracer perf = null; + + if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICY_REQUEST_LOG)) { + perf = RangerPerfTracer.getPerfTracer(PERF_POLICY_REQUEST_LOG, "RangerPolicyEvaluator.evaluate(requestHashCode=" + Integer.toHexString(System.identityHashCode(request)) + "," + + perfTag + ")"); + } + if (request != null && result != null) { boolean isMatchAttempted = false; boolean matchResult = false; @@ -147,18 +173,21 @@ public class RangerDefaultPolicyEvaluator extends RangerAbstractPolicyEvaluator headMatchResult = matchResourceHead(request.getResource()); isHeadMatchAttempted = true; } - } - // Go further to evaluate access only if match or head match was found at this point - if (matchResult || headMatchResult) { - evaluatePolicyItemsForAccess(request, result); - } - } - } + } + // Go further to evaluate access only if match or head match was found at this point + if (matchResult || headMatchResult) { + evaluatePolicyItemsForAccess(request, result); + } + } + } - if(LOG.isDebugEnabled()) { + RangerPerfTracer.log(perf); + + if(LOG.isDebugEnabled()) { LOG.debug("<== RangerDefaultPolicyEvaluator.evaluate(" + request + ", " + result + ")"); } - } + + } protected void evaluatePolicyItemsForAccess(RangerAccessRequest request, RangerAccessResult result) { if(LOG.isDebugEnabled()) { @@ -188,10 +217,18 @@ public class RangerDefaultPolicyEvaluator extends RangerAbstractPolicyEvaluator boolean ret = false; + RangerPerfTracer perf = null; + + if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICY_REQUEST_LOG)) { + perf = RangerPerfTracer.getPerfTracer(PERF_POLICY_REQUEST_LOG, "RangerPolicyEvaluator.isMatch(resource=" + resource.getAsString() + "," + perfTag + ")"); + } + if(resourceMatcher != null) { ret = resourceMatcher.isMatch(resource); } + RangerPerfTracer.log(perf); + if(LOG.isDebugEnabled()) { LOG.debug("<== RangerDefaultPolicyEvaluator.isMatch(" + resource + "): " + ret); } @@ -292,6 +329,11 @@ public class RangerDefaultPolicyEvaluator extends RangerAbstractPolicyEvaluator boolean ret = false; + RangerPerfTracer perf = null; + + if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICY_REQUEST_LOG)) { + perf = RangerPerfTracer.getPerfTracer(PERF_POLICY_REQUEST_LOG, "RangerPolicyEvaluator.isAccessAllowed(hashCode=" + Integer.toHexString(System.identityHashCode(this)) + "," + perfTag + ")"); + } if(CollectionUtils.isNotEmpty(policyItemEvaluators)) { for (RangerPolicyItemEvaluator policyItemEvaluator : policyItemEvaluators) { ret = policyItemEvaluator.matchUserGroup(user, userGroups) && @@ -303,6 +345,8 @@ public class RangerDefaultPolicyEvaluator extends RangerAbstractPolicyEvaluator } } + RangerPerfTracer.log(perf); + if(LOG.isDebugEnabled()) { LOG.debug("<== RangerDefaultPolicyEvaluator.isAccessAllowed(" + user + ", " + userGroups + ", " + accessType + "): " + ret); } @@ -415,6 +459,3 @@ public class RangerDefaultPolicyEvaluator extends RangerAbstractPolicyEvaluator return ret; } } - - - http://git-wip-us.apache.org/repos/asf/incubator-ranger/blob/bec2fefe/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerDefaultPolicyItemEvaluator.java ---------------------------------------------------------------------- diff --git a/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerDefaultPolicyItemEvaluator.java b/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerDefaultPolicyItemEvaluator.java index bf9b243..e8d90fa 100644 --- a/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerDefaultPolicyItemEvaluator.java +++ b/agents-common/src/main/java/org/apache/ranger/plugin/policyevaluator/RangerDefaultPolicyItemEvaluator.java @@ -37,11 +37,16 @@ import org.apache.ranger.plugin.policyengine.RangerAccessRequest; import org.apache.ranger.plugin.policyengine.RangerAccessResult; import org.apache.ranger.plugin.policyengine.RangerPolicyEngine; import org.apache.ranger.plugin.policyengine.RangerPolicyEngineOptions; +import org.apache.ranger.plugin.util.RangerPerfTracer; public class RangerDefaultPolicyItemEvaluator extends RangerAbstractPolicyItemEvaluator { private static final Log LOG = LogFactory.getLog(RangerDefaultPolicyItemEvaluator.class); + private static final Log PERF_POLICYITEM_INIT_LOG = RangerPerfTracer.getPerfLogger("policyitem.init"); + private static final Log PERF_POLICYITEM_REQUEST_LOG = RangerPerfTracer.getPerfLogger("policyitem.request"); + private static final Log PERF_POLICYCONDITION_INIT_LOG = RangerPerfTracer.getPerfLogger("policycondition.init"); + private static final Log PERF_POLICYCONDITION_REQUEST_LOG = RangerPerfTracer.getPerfLogger("policycondition.request"); public RangerDefaultPolicyItemEvaluator(RangerServiceDef serviceDef, RangerPolicy policy, RangerPolicyItem policyItem, RangerPolicyEngineOptions options) { super(serviceDef, policy, policyItem, options); @@ -55,6 +60,12 @@ public class RangerDefaultPolicyItemEvaluator extends RangerAbstractPolicyItemEv if (!getConditionsDisabledOption() && policyItem != null && CollectionUtils.isNotEmpty(policyItem.getConditions())) { conditionEvaluators = new ArrayList<RangerConditionEvaluator>(); + RangerPerfTracer perf = null; + + if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICYITEM_INIT_LOG)) { + perf = RangerPerfTracer.getPerfTracer(PERF_POLICYITEM_INIT_LOG, "RangerPolicyItemEvaluator.init(policyId=" + policyId + ")"); + } + for (RangerPolicyItemCondition condition : policyItem.getConditions()) { RangerPolicyConditionDef conditionDef = getConditionDef(condition.getType()); @@ -69,13 +80,23 @@ public class RangerDefaultPolicyItemEvaluator extends RangerAbstractPolicyItemEv if (conditionEvaluator != null) { conditionEvaluator.setConditionDef(conditionDef); conditionEvaluator.setPolicyItemCondition(condition); + + RangerPerfTracer perfConditionInit = null; + + if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICYCONDITION_INIT_LOG)) { + perfConditionInit = RangerPerfTracer.getPerfTracer(PERF_POLICYCONDITION_INIT_LOG, "RangerConditionEvaluator.init(policyId=" + policyId + ",policyConditionType=" + condition.getType() + ")"); + } + conditionEvaluator.init(); + RangerPerfTracer.log(perfConditionInit); + conditionEvaluators.add(conditionEvaluator); } else { LOG.error("RangerDefaultPolicyItemEvaluator(policyId=" + policyId + "): failed to instantiate condition evaluator '" + condition.getType() + "'; evaluatorClassName='" + conditionDef.getEvaluator() + "'"); } } + RangerPerfTracer.log(perf); } if(LOG.isDebugEnabled()) { @@ -89,6 +110,14 @@ public class RangerDefaultPolicyItemEvaluator extends RangerAbstractPolicyItemEv LOG.debug("==> RangerDefaultPolicyItemEvaluator.evaluate(" + request + ", " + result + ")"); } + boolean ret = false; + + RangerPerfTracer perf = null; + + if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICYITEM_REQUEST_LOG)) { + perf = RangerPerfTracer.getPerfTracer(PERF_POLICYITEM_REQUEST_LOG, "RangerPolicyItemEvaluator.isMatch(resource=" + request.getResource().getAsString() + ")"); + } + if(policyItem != null) { if(matchUserGroup(request.getUser(), request.getUserGroups())) { if (request.isAccessTypeDelegatedAdmin()) { // used only in grant/revoke scenario @@ -125,6 +154,8 @@ public class RangerDefaultPolicyItemEvaluator extends RangerAbstractPolicyItemEv } } + RangerPerfTracer.log(perf); + if(LOG.isDebugEnabled()) { LOG.debug("<== RangerDefaultPolicyItemEvaluator.evaluate(" + request + ", " + result + ")"); } @@ -209,7 +240,24 @@ public class RangerDefaultPolicyItemEvaluator extends RangerAbstractPolicyItemEv if (CollectionUtils.isNotEmpty(conditionEvaluators)) { for(RangerConditionEvaluator conditionEvaluator : conditionEvaluators) { - if(!conditionEvaluator.isMatched(request)) { + if(LOG.isDebugEnabled()) { + LOG.debug("evaluating condition: " + conditionEvaluator); + } + RangerPerfTracer perf = null; + + if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICYCONDITION_REQUEST_LOG)) { + perf = RangerPerfTracer.getPerfTracer(PERF_POLICYCONDITION_REQUEST_LOG, "RangerConditionEvaluator.matchCondition(policyId=" + policyId + ")"); + } + + boolean conditionEvalResult = conditionEvaluator.isMatched(request); + + RangerPerfTracer.log(perf); + + if (!conditionEvalResult) { + if(LOG.isDebugEnabled()) { + LOG.debug(conditionEvaluator + " returned false"); + } + ret = false; break; http://git-wip-us.apache.org/repos/asf/incubator-ranger/blob/bec2fefe/agents-common/src/main/java/org/apache/ranger/plugin/util/PolicyRefresher.java ---------------------------------------------------------------------- diff --git a/agents-common/src/main/java/org/apache/ranger/plugin/util/PolicyRefresher.java b/agents-common/src/main/java/org/apache/ranger/plugin/util/PolicyRefresher.java index 0729339..27968eb 100644 --- a/agents-common/src/main/java/org/apache/ranger/plugin/util/PolicyRefresher.java +++ b/agents-common/src/main/java/org/apache/ranger/plugin/util/PolicyRefresher.java @@ -38,6 +38,8 @@ import com.google.gson.GsonBuilder; public class PolicyRefresher extends Thread { private static final Log LOG = LogFactory.getLog(PolicyRefresher.class); + private static final Log PERF_POLICYENGINE_INIT_LOG = RangerPerfTracer.getPerfLogger("policyengine.init"); + private final RangerBasePlugin plugIn; private final String serviceType; private final String serviceName; @@ -171,7 +173,13 @@ public class PolicyRefresher extends Thread { LOG.debug("==> PolicyRefresher(serviceName=" + serviceName + ").loadPolicy()"); } - //load policy from PolicyAmdin + RangerPerfTracer perf = null; + + if(RangerPerfTracer.isPerfTraceEnabled(PERF_POLICYENGINE_INIT_LOG)) { + perf = RangerPerfTracer.getPerfTracer(PERF_POLICYENGINE_INIT_LOG, "PolicyRefresher.loadPolicy(serviceName=" + serviceName + ")"); + } + + //load policy from PolicyAdmin ServicePolicies svcPolicies = loadPolicyfromPolicyAdmin(); if ( svcPolicies == null) { @@ -183,6 +191,8 @@ public class PolicyRefresher extends Thread { saveToCache(svcPolicies); } + RangerPerfTracer.log(perf); + if (svcPolicies != null) { plugIn.setPolicies(svcPolicies); policiesSetInPlugin = true; http://git-wip-us.apache.org/repos/asf/incubator-ranger/blob/bec2fefe/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfTracer.java ---------------------------------------------------------------------- diff --git a/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfTracer.java b/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfTracer.java index 175c4e4..e130cc7 100644 --- a/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfTracer.java +++ b/agents-common/src/main/java/org/apache/ranger/plugin/util/RangerPerfTracer.java @@ -29,10 +29,12 @@ public class RangerPerfTracer { protected final String data; private final long startTimeMs; + private static long reportingThresholdMs = 0L; + private final static String tagEndMarker = "("; public static Log getPerfLogger(String name) { - return LogFactory.getLog("ranger.perf." + name); + return LogFactory.getLog("org.apache.ranger.perf." + name); } public static Log getPerfLogger(Class<?> cls) { @@ -89,8 +91,9 @@ public class RangerPerfTracer { } public void log() { - if(logger.isDebugEnabled()) { - logger.debug("[PERF] " + tag + data + ": " + getElapsedTime()); + long elapsedTime = getElapsedTime(); + if (elapsedTime > reportingThresholdMs) { + logger.debug("[PERF] " + tag + data + ": " + elapsedTime); } } } http://git-wip-us.apache.org/repos/asf/incubator-ranger/blob/bec2fefe/ranger-tools/conf/log4j.properties ---------------------------------------------------------------------- diff --git a/ranger-tools/conf/log4j.properties b/ranger-tools/conf/log4j.properties index ccb9db4..86f5c18 100644 --- a/ranger-tools/conf/log4j.properties +++ b/ranger-tools/conf/log4j.properties @@ -40,8 +40,8 @@ log4j.appender.console.layout.ConversionPattern=%d{ISO8601} %-5p [%t] %c{2}: %L ranger.perf.logger=DEBUG,PERF ranger.perf.log.file=ranger-perf-test.log -log4j.logger.ranger.perf=${ranger.perf.logger} -log4j.additivity.ranger.perf=false +log4j.logger.org.apache.ranger.perf=${ranger.perf.logger} +log4j.additivity.org.apache.ranger.perf=false log4j.appender.PERF=org.apache.log4j.DailyRollingFileAppender log4j.appender.PERF.File=${ranger.perf.log.file} http://git-wip-us.apache.org/repos/asf/incubator-ranger/blob/bec2fefe/ranger-tools/src/test/resources/log4j.properties ---------------------------------------------------------------------- diff --git a/ranger-tools/src/test/resources/log4j.properties b/ranger-tools/src/test/resources/log4j.properties index abf617e..4ea9d85 100644 --- a/ranger-tools/src/test/resources/log4j.properties +++ b/ranger-tools/src/test/resources/log4j.properties @@ -40,8 +40,8 @@ log4j.appender.console.layout.ConversionPattern=%d{ISO8601} %-5p [%t] %c{2}: %L ranger.perf.logger=DEBUG,PERF ranger.perf.log.file=${java.io.tmpdir}/ranger-perf-test.log -log4j.logger.ranger.perf=${ranger.perf.logger} -log4j.additivity.ranger.perf=false +log4j.logger.org.apache.ranger.perf=${ranger.perf.logger} +log4j.additivity.org.apache.ranger.perf=false log4j.appender.PERF=org.apache.log4j.DailyRollingFileAppender log4j.appender.PERF.File=${ranger.perf.log.file} http://git-wip-us.apache.org/repos/asf/incubator-ranger/blob/bec2fefe/ranger-tools/testdata/test_modules.txt ---------------------------------------------------------------------- diff --git a/ranger-tools/testdata/test_modules.txt b/ranger-tools/testdata/test_modules.txt index 33432ed..9ffcbfc 100644 --- a/ranger-tools/testdata/test_modules.txt +++ b/ranger-tools/testdata/test_modules.txt @@ -17,6 +17,20 @@ # under the License. # +PolicyRefresher.loadPolicy RangerPolicyEngine.init -RangerPolicyEngine.preProcess -RangerPolicyEngine.isAccessAllowedNoAudit +RangerContextEnricher.init +RangerPolicyEvaluator.init +RangerPolicyItemEvaluator.init +RangerConditionEvaluator.init +RangerContextEnricher.enrich +RangerPolicyEngine.isAccessAllowed +RangerPolicyEvaluator.evaluate +RangerPolicyEvaluator.isMatch +RangerPolicyItemEvaluator.isMatch +RangerConditionEvaluator.matchCondition +RangerPolicyEngine.processAudit +RangerTagRefresher.populateTags +RangerPolicyEvaluator.isAccessAllowed +RangerPolicyRetriever.getServicePolicies +RangerTagDBReceiver.getTags
