Repository: casbin/casbin
Pull request #425 (2020-04-16 09:34:03)

Explain enforcement in log
For #355
Explain why an enforcement was or wasn't satisfied.Controlled by `autoExplain` in enforce,Print the policy related to the result to the log.

such as `some(where (p.eft == allow))`, the explanation will be all allowed policy.

whether it hits depends on user selected effect. User can modify it by interface EffectorEx

coveralls: 
[![Coverage Status](https://coveralls.io/builds/30114094/badge)](https://coveralls.io/builds/30114094)

Coverage increased (+1.0%) to 72.786% when pulling **85a441197ef4c7323869bb1620e0a93373a7d9d7 on dovics:explian** into **90d1b93b4a2b07fab0657c8f9c22cddf4bbaf28e on casbin:master**.

hsluoyz: I think logs are not very friendly for users. They want to return matched rules:

```
In some scenarios it would be useful to have a way to explain why an enforcement was or wasn't satisfied.
The simplest idea could be to just inform of the matched rules that allowed satisfying (or not) the model.
```

Can we add a function called `EnforceEx()`, which is similar to `Enforce()`, but returns matched rule(s) additionally?
dovics: the `enforce()` is too long, what do you think of changing the signature of `enforce()`
```
func (e *Enforcer) enforce(matcher string, rvals ...interface{}) (ok bool,explains [][]string,  err error)
```
or
```
func (e *Enforcer) enforce(matcher string, explains *[][]string, rvals ...interface{}) (ok bool, err error)
```

otherwise we need to split `enforce()`, I think it is difficult to do
dovics: I tried adding `EnforceEx()` and `EnforceExWithMatch()`.

I think it is better to return all the policies related to the result. And the result and hitPolicies are returned directly in the return value
nodece: Thanks @dovics , Must approve.  

Patch:
diff --git a/README.md b/README.md
index 6f4e6ba..74e5873 100644
--- a/README.md
+++ b/README.md
@@ -4,7 +4,7 @@ Casbin
 [![Go Report Card](https://goreportcard.com/badge/github.com/casbin/casbin)](https://goreportcard.com/report/github.com/casbin/casbin)
 [![Build Status](https://travis-ci.org/casbin/casbin.svg?branch=master)](https://travis-ci.org/casbin/casbin)
 [![Coverage Status](https://coveralls.io/repos/github/casbin/casbin/badge.svg?branch=master)](https://coveralls.io/github/casbin/casbin?branch=master)
-[![Godoc](https://godoc.org/github.com/casbin/casbin?status.svg)](https://pkg.go.dev/github.com/casbin/casbin/v2)
+[![Godoc](https://godoc.org/github.com/casbin/casbin?status.svg)](https://godoc.org/github.com/casbin/casbin)
 [![Release](https://img.shields.io/github/release/casbin/casbin.svg)](https://github.com/casbin/casbin/releases/latest)
 [![Gitter](https://badges.gitter.im/Join%20Chat.svg)](https://gitter.im/casbin/lobby)
 [![Sourcegraph](https://sourcegraph.com/github.com/casbin/casbin/-/badge.svg)](https://sourcegraph.com/github.com/casbin/casbin?badge)
@@ -25,7 +25,7 @@ production-ready | production-ready | production-ready | production-ready
 [![python](https://casbin.org/img/langs/python.png)](https://github.com/casbin/pycasbin) | [![dotnet](https://casbin.org/img/langs/dotnet.png)](https://github.com/casbin-net/Casbin.NET) | [![delphi](https://casbin.org/img/langs/delphi.png)](https://github.com/casbin4d/Casbin4D) | [![rust](https://casbin.org/img/langs/rust.png)](https://github.com/casbin/casbin-rs)
 ----|----|----|----
 [PyCasbin](https://github.com/casbin/pycasbin) | [Casbin.NET](https://github.com/casbin-net/Casbin.NET) | [Casbin4D](https://github.com/casbin4d/Casbin4D) | [Casbin-RS](https://github.com/casbin/casbin-rs)
-production-ready | production-ready | experimental | production-ready
+production-ready | production-ready | experimental | WIP
 
 ## Table of contents
 
diff --git a/effect/default_effector.go b/effect/default_effector.go
index bf8ae80..8fe7f16 100644
--- a/effect/default_effector.go
+++ b/effect/default_effector.go
@@ -27,49 +27,54 @@ func NewDefaultEffector() *DefaultEffector {
 }
 
 // MergeEffects merges all matching results collected by the enforcer into a single decision.
-func (e *DefaultEffector) MergeEffects(expr string, effects []Effect, results []float64) (bool, error) {
+func (e *DefaultEffector) MergeEffects(expr string, effects []Effect, results []float64) (bool, int, error) {
 	result := false
+	explainIndex := -1
 	if expr == "some(where (p_eft == allow))" {
 		result = false
-		for _, eft := range effects {
+		for i, eft := range effects {
 			if eft == Allow {
 				result = true
+				explainIndex = i
 				break
 			}
 		}
 	} else if expr == "!some(where (p_eft == deny))" {
 		result = true
-		for _, eft := range effects {
+		for i, eft := range effects {
 			if eft == Deny {
 				result = false
+				explainIndex = i
 				break
 			}
 		}
 	} else if expr == "some(where (p_eft == allow)) && !some(where (p_eft == deny))" {
 		result = false
-		for _, eft := range effects {
+		for i, eft := range effects {
 			if eft == Allow {
 				result = true
 			} else if eft == Deny {
 				result = false
+				explainIndex = i
 				break
 			}
 		}
 	} else if expr == "priority(p_eft) || deny" {
 		result = false
-		for _, eft := range effects {
+		for i, eft := range effects {
 			if eft != Indeterminate {
 				if eft == Allow {
 					result = true
 				} else {
 					result = false
 				}
+				explainIndex = i
 				break
 			}
 		}
 	} else {
-		return false, errors.New("unsupported effect")
+		return false, -1, errors.New("unsupported effect")
 	}
 
-	return result, nil
+	return result, explainIndex, nil
 }
diff --git a/effect/effector.go b/effect/effector.go
index 52271b3..d48ce23 100644
--- a/effect/effector.go
+++ b/effect/effector.go
@@ -27,5 +27,5 @@ const (
 // Effector is the interface for Casbin effectors.
 type Effector interface {
 	// MergeEffects merges all matching results collected by the enforcer into a single decision.
-	MergeEffects(expr string, effects []Effect, results []float64) (bool, error)
+	MergeEffects(expr string, effects []Effect, results []float64) (bool, int, error)
 }
diff --git a/enforcer.go b/enforcer.go
index ec5179f..4d6f794 100644
--- a/enforcer.go
+++ b/enforcer.go
@@ -344,7 +344,7 @@ func (e *Enforcer) BuildRoleLinks() error {
 }
 
 // enforce use a custom matcher to decides whether a "subject" can access a "object" with the operation "action", input parameters are usually: (matcher, sub, obj, act), use model matcher by default when matcher is "".
-func (e *Enforcer) enforce(matcher string, rvals ...interface{}) (ok bool, err error) {
+func (e *Enforcer) enforce(matcher string, explains *[]string, rvals ...interface{}) (ok bool, err error) {
 	defer func() {
 		if r := recover(); r != nil {
 			err = fmt.Errorf("panic: %v", r)
@@ -394,6 +394,7 @@ func (e *Enforcer) enforce(matcher string, rvals ...interface{}) (ok bool, err e
 
 	var policyEffects []effect.Effect
 	var matcherResults []float64
+
 	if policyLen := len(e.model["p"]["p"].Policy); policyLen != 0 {
 		policyEffects = make([]effect.Effect, policyLen)
 		matcherResults = make([]float64, policyLen)
@@ -480,11 +481,17 @@ func (e *Enforcer) enforce(matcher string, rvals ...interface{}) (ok bool, err e
 
 	// log.LogPrint("Rule Results: ", policyEffects)
 
-	result, err := e.eft.MergeEffects(e.model["e"]["e"].Value, policyEffects, matcherResults)
+	result, explainIndex, err := e.eft.MergeEffects(e.model["e"]["e"].Value, policyEffects, matcherResults)
 	if err != nil {
 		return false, err
 	}
 
+	if explains != nil {
+		if explainIndex != -1 {
+			*explains = e.model["p"]["p"].Policy[explainIndex]
+		}
+	}
+
 	// Log request.
 	if log.GetLogger().IsEnabled() {
 		var reqStr strings.Builder
@@ -496,7 +503,20 @@ func (e *Enforcer) enforce(matcher string, rvals ...interface{}) (ok bool, err e
 				reqStr.WriteString(fmt.Sprintf("%v", rval))
 			}
 		}
-		reqStr.WriteString(fmt.Sprintf(" ---> %t", result))
+		reqStr.WriteString(fmt.Sprintf(" ---> %t\n", result))
+
+		if explains != nil {
+			reqStr.WriteString("Hit Policy: ")
+			for i, pval := range *explains {
+				if i != len(*explains)-1 {
+					reqStr.WriteString(fmt.Sprintf("%v, ", pval))
+				} else {
+					reqStr.WriteString(fmt.Sprintf("%v \n", pval))
+				}
+			}
+
+		}
+
 		log.LogPrint(reqStr.String())
 	}
 
@@ -505,12 +525,26 @@ func (e *Enforcer) enforce(matcher string, rvals ...interface{}) (ok bool, err e
 
 // Enforce decides whether a "subject" can access a "object" with the operation "action", input parameters are usually: (sub, obj, act).
 func (e *Enforcer) Enforce(rvals ...interface{}) (bool, error) {
-	return e.enforce("", rvals...)
+	return e.enforce("", nil, rvals...)
 }
 
 // EnforceWithMatcher use a custom matcher to decides whether a "subject" can access a "object" with the operation "action", input parameters are usually: (matcher, sub, obj, act), use model matcher by default when matcher is "".
 func (e *Enforcer) EnforceWithMatcher(matcher string, rvals ...interface{}) (bool, error) {
-	return e.enforce(matcher, rvals...)
+	return e.enforce(matcher, nil, rvals...)
+}
+
+// EnforceEx explain enforcement by informing matched rules
+func (e *Enforcer) EnforceEx(rvals ...interface{}) (bool, []string, error) {
+	explain := []string{}
+	result, err := e.enforce("", &explain, rvals...)
+	return result, explain, err
+}
+
+// EnforceExWithMatcher use a custom matcher and explain enforcement by informing matched rules
+func (e *Enforcer) EnforceExWithMatcher(matcher string, rvals ...interface{}) (bool, []string, error) {
+	explain := []string{}
+	result, err := e.enforce(matcher, &explain, rvals...)
+	return result, explain, err
 }
 
 // assumes bounds have already been checked
diff --git a/enforcer_interface.go b/enforcer_interface.go
index e0f3ba0..016f967 100644
--- a/enforcer_interface.go
+++ b/enforcer_interface.go
@@ -37,7 +37,7 @@ type IEnforcer interface {
 	GetAdapter() persist.Adapter
 	SetAdapter(adapter persist.Adapter)
 	SetWatcher(watcher persist.Watcher) error
-	GetRoleManager() rbac.RoleManager;
+	GetRoleManager() rbac.RoleManager
 	SetRoleManager(rm rbac.RoleManager)
 	SetEffector(eft effect.Effector)
 	ClearPolicy()
@@ -51,9 +51,11 @@ type IEnforcer interface {
 	EnableAutoSave(autoSave bool)
 	EnableAutoBuildRoleLinks(autoBuildRoleLinks bool)
 	BuildRoleLinks() error
-	enforce(matcher string, rvals ...interface{}) (bool, error)
+	enforce(matcher string, explains *[]string, rvals ...interface{}) (bool, error)
 	Enforce(rvals ...interface{}) (bool, error)
 	EnforceWithMatcher(matcher string, rvals ...interface{}) (bool, error)
+	EnforceEx(rvals ...interface{}) (bool, []string, error)
+	EnforceExWithMatcher(matcher string, rvals ...interface{}) (bool, []string, error)
 
 	/* RBAC API */
 	GetRolesForUser(name string) ([]string, error)
@@ -75,11 +77,11 @@ type IEnforcer interface {
 	DeletePermission(permission ...string) (bool, error)
 
 	/* RBAC API with domains*/
-	GetUsersForRoleInDomain(name string, domain string) []string;
-	GetRolesForUserInDomain(name string, domain string) []string;
-	GetPermissionsForUserInDomain(user string, domain string) [][]string;
-	AddRoleForUserInDomain(user string, role string, domain string) (bool, error);
-	DeleteRoleForUserInDomain(user string, role string, domain string) (bool, error);
+	GetUsersForRoleInDomain(name string, domain string) []string
+	GetRolesForUserInDomain(name string, domain string) []string
+	GetPermissionsForUserInDomain(user string, domain string) [][]string
+	AddRoleForUserInDomain(user string, role string, domain string) (bool, error)
+	DeleteRoleForUserInDomain(user string, role string, domain string) (bool, error)
 
 	/* Management API */
 	GetAllSubjects() []string
diff --git a/util/util.go b/util/util.go
index e25dc22..3a1e359 100644
--- a/util/util.go
+++ b/util/util.go
@@ -23,8 +23,8 @@ import (
 // EscapeAssertion escapes the dots in the assertion, because the expression evaluation doesn't support such variable names.
 func EscapeAssertion(s string) string {
 	//Replace the first dot, because it can't be recognized by the regexp.
-	if (strings.HasPrefix(s, "r") || strings.HasPrefix(s, "p")) {
-		s = strings.Replace(s, ".", "_",1)
+	if strings.HasPrefix(s, "r") || strings.HasPrefix(s, "p") {
+		s = strings.Replace(s, ".", "_", 1)
 	}
 	var regex = regexp.MustCompile(`(\|| |=|\)|\(|&|<|>|,|\+|-|!|\*|\/)(r|p)\.`)
 	s = regex.ReplaceAllStringFunc(s, func(m string) string {


Test patch:
diff --git a/enforcer_test.go b/enforcer_test.go
index 6d007d0..726a04f 100644
--- a/enforcer_test.go
+++ b/enforcer_test.go
@@ -20,6 +20,7 @@ import (
 
 	"github.com/casbin/casbin/v2/model"
 	fileadapter "github.com/casbin/casbin/v2/persist/file-adapter"
+	"github.com/casbin/casbin/v2/util"
 )
 
 func TestKeyMatchModelInMemory(t *testing.T) {
@@ -419,3 +420,58 @@ func TestInitEmpty(t *testing.T) {
 
 	testEnforce(t, e, "alice", "/alice_data/resource1", "GET", true)
 }
+func testEnforceEx(t *testing.T, e *Enforcer, sub string, obj string, act string, res []string) {
+	t.Helper()
+	_, myRes, _ := e.EnforceEx(sub, obj, act)
+
+	if ok := util.ArrayEquals(res, myRes); !ok {
+		t.Error("Key: ", myRes, ", supposed to be ", res)
+	}
+}
+
+func TestEnforceEx(t *testing.T) {
+	e, _ := NewEnforcer("examples/basic_model.conf", "examples/basic_policy.csv")
+
+	testEnforceEx(t, e, "alice", "data1", "read", []string{"alice", "data1", "read"})
+	testEnforceEx(t, e, "alice", "data1", "write", []string{})
+	testEnforceEx(t, e, "alice", "data2", "read", []string{})
+	testEnforceEx(t, e, "alice", "data2", "write", []string{})
+	testEnforceEx(t, e, "bob", "data1", "read", []string{})
+	testEnforceEx(t, e, "bob", "data1", "write", []string{})
+	testEnforceEx(t, e, "bob", "data2", "read", []string{})
+	testEnforceEx(t, e, "bob", "data2", "write", []string{"bob", "data2", "write"})
+
+	e, _ = NewEnforcer("examples/rbac_model.conf", "examples/rbac_policy.csv")
+
+	testEnforceEx(t, e, "alice", "data1", "read", []string{"alice", "data1", "read"})
+	testEnforceEx(t, e, "alice", "data1", "write", []string{})
+	testEnforceEx(t, e, "alice", "data2", "read", []string{"data2_admin", "data2", "read"})
+	testEnforceEx(t, e, "alice", "data2", "write", []string{"data2_admin", "data2", "write"})
+	testEnforceEx(t, e, "bob", "data1", "read", []string{})
+	testEnforceEx(t, e, "bob", "data1", "write", []string{})
+	testEnforceEx(t, e, "bob", "data2", "read", []string{})
+	testEnforceEx(t, e, "bob", "data2", "write", []string{"bob", "data2", "write"})
+
+	e, _ = NewEnforcer("examples/priority_model.conf", "examples/priority_policy.csv")
+
+	testEnforceEx(t, e, "alice", "data1", "read", []string{"alice", "data1", "read", "allow"})
+	testEnforceEx(t, e, "alice", "data1", "write", []string{"data1_deny_group", "data1", "write", "deny"})
+	testEnforceEx(t, e, "alice", "data2", "read", []string{})
+	testEnforceEx(t, e, "alice", "data2", "write", []string{})
+	testEnforceEx(t, e, "bob", "data1", "write", []string{})
+	testEnforceEx(t, e, "bob", "data2", "read", []string{"data2_allow_group", "data2", "read", "allow"})
+	testEnforceEx(t, e, "bob", "data2", "write", []string{"bob", "data2", "write", "deny"})
+}
+
+func TestEnforceExLog(t *testing.T) {
+	e, _ := NewEnforcer("examples/basic_model.conf", "examples/basic_policy.csv", true)
+
+	testEnforceEx(t, e, "alice", "data1", "read", []string{"alice", "data1", "read"})
+	testEnforceEx(t, e, "alice", "data1", "write", []string{})
+	testEnforceEx(t, e, "alice", "data2", "read", []string{})
+	testEnforceEx(t, e, "alice", "data2", "write", []string{})
+	testEnforceEx(t, e, "bob", "data1", "read", []string{})
+	testEnforceEx(t, e, "bob", "data1", "write", []string{})
+	testEnforceEx(t, e, "bob", "data2", "read", []string{})
+	testEnforceEx(t, e, "bob", "data2", "write", []string{"bob", "data2", "write"})
+}
diff --git a/management_api_test.go b/management_api_test.go
index fc2e4d8..fad5d31 100644
--- a/management_api_test.go
+++ b/management_api_test.go
@@ -154,11 +154,11 @@ func TestModifyPolicyAPI(t *testing.T) {
 	e.AddPolicy("eve", "data3", "read")
 	e.AddPolicy("eve", "data3", "read")
 
-	rules :=[][] string {
-				[]string {"jack", "data4", "read"},
-				[]string {"katy", "data4", "write"},
-				[]string {"leyo", "data4", "read"},
-				[]string {"ham", "data4", "write"},
+	rules := [][]string{
+		{"jack", "data4", "read"},
+		{"katy", "data4", "write"},
+		{"leyo", "data4", "read"},
+		{"ham", "data4", "write"},
 	}
 
 	e.AddPolicies(rules)
@@ -202,9 +202,9 @@ func TestModifyGroupingPolicyAPI(t *testing.T) {
 	e.AddGroupingPolicy("bob", "data1_admin")
 	e.AddGroupingPolicy("eve", "data3_admin")
 
-	groupingRules := [][]string {
-					{"ham", "data4_admin"},
-					{"jack", "data5_admin"},
+	groupingRules := [][]string{
+		{"ham", "data4_admin"},
+		{"jack", "data5_admin"},
 	}
 
 	e.AddGroupingPolicies(groupingRules)