Repository: casbin/casbin
Pull request #626 (2020-10-19 16:38:09)

feat: Improve logger
Fix: https://github.com/casbin/casbin/issues/234

Improve the logger function.

hsluoyz: @kocoler fix CI.
kocoler: @hsluoyz already fixed.
hsluoyz: @nodece @GopherJ @dovics please review.
nodece: @kocoler I suggest that you add an EnforceLog interface to the log folder, you don't need to change the currently log, EnforceLog only records enforce log. 

@hsluoyz what do you think?


hsluoyz: I think we should have a clear idea about why we are refactoring the logging.

From my opinion, we already have a logger interface, and an default logger that implements the logger. Next we should focus on how to implement other loggers that use the No.1, No.2 open-source Golang loggers. In such process, we may found places to improve inside our logger interface. Then we iterate to improve it. I think this is how the entire process works.
nodece: @hsluoyz sounds great.  It is important that improve the currently log interface. A good idea that provides different level log.

Patch:
diff --git a/enforcer.go b/enforcer.go
index 88e3fd6..ab0aec8 100644
--- a/enforcer.go
+++ b/enforcer.go
@@ -561,7 +561,12 @@ func (e *Enforcer) enforce(matcher string, explains *[]string, rvals ...interfac
 
 		}
 
-		log.LogPrint(reqStr.String())
+		logType := log.LogTypeGrantedAccessRequest
+		if !result {
+			logType = log.LogTypeRejectedAccessRequest
+		}
+
+		log.LogEnforce(logType, reqStr.String(), &rvals, explains, &[]interface{}{result})
 	}
 
 	return result, nil
diff --git a/enforcer_synced.go b/enforcer_synced.go
index 41fedd6..c61d693 100644
--- a/enforcer_synced.go
+++ b/enforcer_synced.go
@@ -65,7 +65,8 @@ func (e *SyncedEnforcer) StartAutoLoadPolicy(d time.Duration) {
 			atomic.StoreInt32(&(e.autoLoadRunning), int32(0))
 		}()
 		n := 1
-		log.LogPrintf("Start automatically load policy")
+		//log.LogPrintf("Start automatically load policy")
+		log.LogPolicy(log.LogTypeLoadPolicy, "Start automatically load policy", nil, nil, nil, nil)
 		for {
 			select {
 			case <-ticker.C:
@@ -75,7 +76,8 @@ func (e *SyncedEnforcer) StartAutoLoadPolicy(d time.Duration) {
 				// log.Print("Load policy for time: ", n)
 				n++
 			case <-e.stopAutoLoad:
-				log.LogPrintf("Stop automatically load policy")
+				//log.LogPrintf("Stop automatically load policy")
+				log.LogPolicy(log.LogTypeLoadPolicy, "Stop automatically load policy", nil, nil, nil, nil)
 				return
 			}
 		}
diff --git a/log/default_logger.go b/log/default_logger.go
index 5e5967e..6950907 100644
--- a/log/default_logger.go
+++ b/log/default_logger.go
@@ -36,14 +36,38 @@ func (l *DefaultLogger) IsEnabled() bool {
 	return atomic.LoadInt32(&(l.enable)) != 0
 }
 
-func (l *DefaultLogger) Print(v ...interface{}) {
-	if l.IsEnabled() {
-		log.Print(v...)
+func (l *DefaultLogger) LogModel(event int, line []string, model [][]string) {
+	for _, v := range line {
+		log.Print(v)
 	}
 }
 
+func (l *DefaultLogger) LogEnforce(event int, line string, request *[]interface{}, policies *[]string, result *[]interface{}) {
+	log.Print(line)
+}
+
+func (l *DefaultLogger) LogPolicy(event int, line string, pPolicyFormat []string, gPolicyFormat []string, pPolicy *[]interface{}, gPolicy *[]interface{}) {
+	log.Print(line)
+	if pPolicy != nil {
+		for k, v := range *pPolicy {
+			log.Print("p: ", pPolicyFormat[k], ": ", v)
+		}
+	}
+	if gPolicy != nil {
+		for k, v := range *gPolicy {
+			log.Print("g: ", gPolicyFormat[k], ": ", v)
+		}
+	}
+}
+
+func (l *DefaultLogger) LogRole(event int, line string, role []string) {
+	log.Print(line)
+}
+
+/*
 func (l *DefaultLogger) Printf(format string, v ...interface{}) {
 	if l.IsEnabled() {
 		log.Printf(format, v...)
 	}
 }
+*/
diff --git a/log/log_util.go b/log/log_util.go
index ef4b816..f789ae6 100644
--- a/log/log_util.go
+++ b/log/log_util.go
@@ -26,6 +26,7 @@ func GetLogger() Logger {
 	return logger
 }
 
+/*
 // LogPrint prints the log.
 func LogPrint(v ...interface{}) {
 	logger.Print(v...)
@@ -35,3 +36,24 @@ func LogPrint(v ...interface{}) {
 func LogPrintf(format string, v ...interface{}) {
 	logger.Printf(format, v...)
 }
+*/
+
+// LogModel logs the model information.
+func LogModel(event int, line []string, model [][]string) {
+	logger.LogModel(event, line, model)
+}
+
+// LogEnforce logs the enforcer information.
+func LogEnforce(event int, line string, request *[]interface{}, policies *[]string, result *[]interface{}) {
+	logger.LogEnforce(event, line, request, policies, result)
+}
+
+// LogRole logs the role information.
+func LogRole(event int, line string, role []string) {
+	logger.LogRole(event, line, role)
+}
+
+// LogPolicy logs the policy information.
+func LogPolicy(event int, line string, pPolicyFormat []string, gPolicyFormat []string, pPolicy *[]interface{}, gPolicy *[]interface{}) {
+	logger.LogPolicy(event, line, pPolicyFormat, gPolicyFormat, pPolicy, gPolicy)
+}
diff --git a/log/logger.go b/log/logger.go
index e3aadd1..6f7c40e 100644
--- a/log/logger.go
+++ b/log/logger.go
@@ -14,6 +14,16 @@
 
 package log
 
+const (
+	LogTypeGrantedAccessRequest = iota
+	LogTypeRejectedAccessRequest
+	LogTypeLoadPolicy
+	LogTypePrintModel
+	LogTypePrintPolicy
+	LogTypePrintRole
+	LogTypeLinkRole
+)
+
 // Logger is the logging interface implementation.
 type Logger interface {
 	//EnableLog controls whether print the message.
@@ -23,8 +33,20 @@ type Logger interface {
 	IsEnabled() bool
 
 	//Print formats using the default formats for its operands and logs the message.
-	Print(...interface{})
+	//Print(...interface{})
 
 	//Printf formats according to a format specifier and logs the message.
-	Printf(string, ...interface{})
+	//Printf(string, ...interface{})
+
+	// LogModel log info related to model.
+	LogModel(event int, line []string, model [][]string)
+
+	// LogEnforce log info related to enforce.
+	LogEnforce(event int, line string, request *[]interface{}, policies *[]string, result *[]interface{})
+
+	// LogRole log info related to role.
+	LogRole(event int, line string, role []string)
+
+	// LogPolicy log info related to policy.
+	LogPolicy(event int, line string, pPolicyFormat []string, gPolicyFormat []string, pPolicy *[]interface{}, gPolicy *[]interface{})
 }
diff --git a/model/assertion.go b/model/assertion.go
index 49387d8..7ea850f 100644
--- a/model/assertion.go
+++ b/model/assertion.go
@@ -83,7 +83,8 @@ func (ast *Assertion) buildRoleLinks(rm rbac.RoleManager) error {
 		}
 	}
 
-	log.LogPrint("Role links for: " + ast.Key)
+	//log.LogPrint("Role links for: " + ast.Key)
+	log.LogRole(log.LogTypeLinkRole, "Role links for: " + ast.Key, []string{ast.Key})
 
 	return ast.RM.PrintRoles()
 }
diff --git a/model/model.go b/model/model.go
index 99b0758..4c7bd00 100644
--- a/model/model.go
+++ b/model/model.go
@@ -167,10 +167,16 @@ func (model Model) hasSection(sec string) bool {
 
 // PrintModel prints the model to the log.
 func (model Model) PrintModel() {
-	log.LogPrint("Model:")
+	//log.LogPrint("Model:")
+	logInfo := []string{"Model"}
+	var modelInfo [][]string
 	for k, v := range model {
 		for i, j := range v {
-			log.LogPrintf("%s.%s: %s", k, i, j.Value)
+			modelInfo = append(modelInfo, []string{k, i, j.Value})
+			logInfo = append(logInfo, fmt.Sprintf("%s.%s: %s", k, i, j.Value))
+			//log.LogPrintf("%s.%s: %s", k, i, j.Value)
 		}
 	}
+
+	log.LogModel(log.LogTypePrintModel, logInfo, modelInfo)
 }
diff --git a/model/policy.go b/model/policy.go
index 0cfc99d..69a2fc0 100644
--- a/model/policy.go
+++ b/model/policy.go
@@ -59,14 +59,27 @@ func (model Model) PrintPolicy() {
 	if !log.GetLogger().IsEnabled() {
 		return
 	}
-	log.LogPrint("Policy:")
-	for key, ast := range model["p"] {
-		log.LogPrint(key, ": ", ast.Value, ": ", ast.Policy)
+	//log.LogPrint("Policy:")
+	var (
+		pPolicy       []interface{} // or [][][]string
+		gPolicy       []interface{}
+		pPolicyFormat []string
+		gPolicyFormat []string
+	)
+
+	for _, ast := range model["p"] {
+		pPolicyFormat = append(pPolicyFormat, ast.Value)
+		pPolicy = append(pPolicy, ast.Policy)
+		//log.LogPrint(key, ": ", ast.Value, ": ", ast.Policy)
 	}
 
-	for key, ast := range model["g"] {
-		log.LogPrint(key, ": ", ast.Value, ": ", ast.Policy)
+	for _, ast := range model["g"] {
+		gPolicyFormat = append(gPolicyFormat, ast.Value)
+		gPolicy = append(gPolicy, ast.Policy)
+		//log.LogPrint(key, ": ", ast.Value, ": ", ast.Policy)
 	}
+
+	log.LogPolicy(log.LogTypePrintPolicy, "Policy: ", pPolicyFormat, gPolicyFormat, &pPolicy, &gPolicy)
 }
 
 // ClearPolicy clears all current policy.
diff --git a/rbac/default-role-manager/role_manager.go b/rbac/default-role-manager/role_manager.go
index 98d4c23..c03c542 100644
--- a/rbac/default-role-manager/role_manager.go
+++ b/rbac/default-role-manager/role_manager.go
@@ -230,12 +230,14 @@ func (rm *RoleManager) GetUsers(name string, domain ...string) ([]string, error)
 func (rm *RoleManager) PrintRoles() error {
 	if log.GetLogger().IsEnabled() {
 		var sb strings.Builder
+		var roles []string
 		rm.allDomains.Range(func(_, value interface{}) bool {
 			value.(*Roles).Range(func(_, value interface{}) bool {
 				if text := value.(*Role).toString(); text != "" {
 					if sb.Len() == 0 {
 						sb.WriteString(text)
 					} else {
+						roles = append(roles, text)
 						sb.WriteString(", ")
 						sb.WriteString(text)
 					}
@@ -245,7 +247,8 @@ func (rm *RoleManager) PrintRoles() error {
 
 			return true
 		})
-		log.LogPrint(sb.String())
+		//log.LogPrint(sb.String())
+		log.LogRole(log.LogTypePrintRole, sb.String(), roles)
 	}
 	return nil
 }


Test patch:
diff --git a/log/log_util_test.go b/log/log_util_test.go
index 72cd56b..e989798 100644
--- a/log/log_util_test.go
+++ b/log/log_util_test.go
@@ -20,34 +20,49 @@ import (
 )
 
 type LoggerTester struct {
-	format      string
+	event       int
+	line        string
 	lastMessage []interface{}
 }
 
 func (t *LoggerTester) EnableLog(bool)  {}
 func (t *LoggerTester) IsEnabled() bool { return true }
 
-func (t *LoggerTester) Print(v ...interface{}) {
-	t.format = ""
-	t.lastMessage = v
+func (t *LoggerTester) LogModel(event int, line []string, model [][]string) {
+	t.event = event
+	t.line = ""
+	t.lastMessage = []interface{}{model}
 }
 
-func (t *LoggerTester) Printf(format string, v ...interface{}) {
-	t.format = format
-	t.lastMessage = v
+func (t *LoggerTester) LogEnforce(event int, line string, request *[]interface{}, policies *[]string, result *[]interface{}) {
+	t.event = event
+	t.line = ""
+	t.lastMessage = *request
+}
+
+func (t *LoggerTester) LogRole(event int, line string, role []string) {
+	t.event = event
+	t.line = ""
+	t.lastMessage = []interface{}{role}
+}
+
+func (t *LoggerTester) LogPolicy(event int, line string, pPolicyFormat []string, gPolicyFormat []string, pPolicy *[]interface{}, gPolicy *[]interface{}) {
+	t.event = event
+	t.line = ""
+	t.lastMessage = []interface{}{pPolicyFormat, gPolicyFormat, pPolicy, gPolicy}
 }
 
 func TestLog(t *testing.T) {
 	lt := &LoggerTester{}
 	SetLogger(lt)
 
-	LogPrint(1, "1", true)
-	if lt.format != "" || !reflect.DeepEqual(lt.lastMessage, []interface{}{1, "1", true}) {
+	LogEnforce(1, "2", &[]interface{}{"3"}, &[]string{"4"}, &[]interface{}{true})
+	if lt.event != 1 || lt.line != "" || !reflect.DeepEqual(lt.lastMessage, []interface{}{"3"}) {
 		t.Errorf("incorrect logger message: %+v", lt.lastMessage)
 	}
 
-	LogPrintf("%d", 2, "2", false)
-	if lt.format != "%d" || !reflect.DeepEqual(lt.lastMessage, []interface{}{2, "2", false}) {
+	LogModel(1, []string{"2"}, [][]string{{"3", "4"}})
+	if lt.event != 1 || lt.line != "" || !reflect.DeepEqual(lt.lastMessage, []interface{}{[][]string{{"3", "4"}}}) {
 		t.Errorf("incorrect logger message: %+v", lt.lastMessage)
 	}
 }