Optimize logging of loading rules in rule managers

Author: louyuting

core/circuitbreaker/rule_manager.go

@@ -3,7 +3,6 @@ package circuitbreaker
 import (
 	"fmt"
 	"reflect"
-	"strings"
 	"sync"
 
 	"github.com/alibaba/sentinel-golang/logging"
@@ -284,15 +283,13 @@ func rulesFrom(rm map[string][]*Rule) []*Rule {
 	return rules
 }
 
-func logRuleUpdate(rules map[string][]*Rule) {
-	sb := strings.Builder{}
-	sb.WriteString("Circuit breaking rules loaded: [")
-
-	for _, r := range rulesFrom(rules) {
-		sb.WriteString(r.String() + ",")
+func logRuleUpdate(m map[string][]*Rule) {
+	rs := rulesFrom(m)
+	if len(rs) == 0 {
+		logging.Info("[CircuitBreakerRuleManager] Circuit breaking rules were cleared")
+	} else {
+		logging.Info("[CircuitBreakerRuleManager] Circuit breaking rules were loaded", "rules", rs)
 	}
-	sb.WriteString("]")
-	logging.Info(sb.String())
 }
 
 // Note: this function is not thread-safe.

core/flow/rule_manager.go

@@ -1,7 +1,6 @@
 package flow
 
 import (
-	"encoding/json"
 	"fmt"
 	"sync"
 
@@ -56,19 +55,11 @@ func init() {
 }
 
 func logRuleUpdate(m TrafficControllerMap) {
-	bs, err := json.Marshal(rulesFrom(m))
-	if err != nil {
-		if len(m) == 0 {
-			logging.Info("[FlowRuleManager] Flow rules were cleared")
-		} else {
-			logging.Info("[FlowRuleManager] Flow rules were loaded")
-		}
+	rs := rulesFrom(m)
+	if len(rs) == 0 {
+		logging.Info("[FlowRuleManager] Flow rules were cleared")
 	} else {
-		if len(m) == 0 {
-			logging.Info("[FlowRuleManager] Flow rules were cleared")
-		} else {
-			logging.Info("[FlowRuleManager] Flow rules were loaded", "rules", string(bs))
-		}
+		logging.Info("[FlowRuleManager] Flow rules were loaded", "rules", rs)
 	}
 }
 

core/flow/slot.go

@@ -60,7 +60,9 @@ func selectNodeByRelStrategy(rule *Rule, node base.StatNode) base.StatNode {
 func checkInLocal(tc *TrafficShapingController, node base.StatNode, acquireCount uint32, flag int32) *base.TokenResult {
 	actual := selectNodeByRelStrategy(tc.rule, node)
 	if actual == nil {
-		logging.Error(errors.Errorf("nil resource node"), "no resource node for flow rule", "rule", tc.rule)
+		logging.FrequentErrorOnce.Do(func() {
+			logging.Error(errors.Errorf("nil resource node"), "no resource node for flow rule", "rule", tc.rule)
+		})
 		return base.NewTokenResultPass()
 	}
 	return tc.PerformChecking(node, acquireCount, flag)

core/hotspot/rule_manager.go

@@ -2,7 +2,6 @@ package hotspot
 
 import (
 	"fmt"
-	"strings"
 	"sync"
 
 	"github.com/alibaba/sentinel-golang/logging"
@@ -197,14 +196,12 @@ func onRuleUpdate(rules []*Rule) (err error) {
 }
 
 func logRuleUpdate(m trafficControllerMap) {
-	sb := strings.Builder{}
-	sb.WriteString("Hotspot parameter flow control rules loaded: [")
-
-	for _, r := range rulesFrom(m) {
-		sb.WriteString(r.String() + ",")
+	rs := rulesFrom(m)
+	if len(rs) == 0 {
+		logging.Info("[HotspotRuleManager] Hotspot rules were cleared")
+	} else {
+		logging.Info("[HotspotRuleManager] Hotspot rules were loaded", "rules", rs)
 	}
-	sb.WriteString("]")
-	logging.Info(sb.String())
 }
 
 func rulesFrom(m trafficControllerMap) []*Rule {

core/isolation/rule_manager.go

@@ -1,7 +1,6 @@
 package isolation
 
 import (
-	"encoding/json"
 	"sync"
 
 	"github.com/alibaba/sentinel-golang/logging"
@@ -113,19 +112,11 @@ func rulesFrom(m map[string][]*Rule) []*Rule {
 }
 
 func logRuleUpdate(m map[string][]*Rule) {
-	bs, err := json.Marshal(rulesFrom(m))
-	if err != nil {
-		if len(m) == 0 {
-			logging.Info("[IsolationRuleManager] Isolation rules were cleared")
-		} else {
-			logging.Info("[IsolationRuleManager] Isolation rules were loaded")
-		}
+	rs := rulesFrom(m)
+	if len(rs) == 0 {
+		logging.Info("[IsolationRuleManager] Isolation rules were cleared")
 	} else {
-		if len(m) == 0 {
-			logging.Info("[IsolationRuleManager] Isolation rules were cleared")
-		} else {
-			logging.Info("[IsolationRuleManager] Isolation rules were loaded", "rules", string(bs))
-		}
+		logging.Info("[IsolationRuleManager] Isolation rules were loaded", "rules", rs)
 	}
 }
 

logging/logging.go

@@ -8,6 +8,7 @@ import (
 	"os"
 	"runtime"
 	"strings"
+	"sync"
 	"time"
 )
 
@@ -25,12 +26,14 @@ const (
 	// RecordLogFileName represents the default file name of the record log.
 	RecordLogFileName = "sentinel-record.log"
 	DefaultDirName    = "logs" + string(os.PathSeparator) + "csp" + string(os.PathSeparator)
+	GlobalCallerDepth = 4
 )
 
 var (
-	globalLogLevel    = InfoLevel
-	globalCallerDepth = 4
-	globalLogger      = NewConsoleLogger()
+	globalLogLevel = InfoLevel
+	globalLogger   = NewConsoleLogger()
+
+	FrequentErrorOnce = &sync.Once{}
 )
 
 func GetGlobalLoggerLevel() Level {
@@ -169,12 +172,19 @@ func AssembleMsg(depth int, logLevel, msg string, err error, keysAndValues ...in
 			sb.WriteString(kStr)
 			sb.WriteByte('"')
 			sb.WriteByte(':')
-			if vbs, err := json.Marshal(v); err != nil {
+			vStr, vIsStr := v.(string)
+			if !vIsStr {
+				if vbs, err := json.Marshal(v); err != nil {
+					sb.WriteByte('"')
+					sb.WriteString(fmt.Sprintf("%+v", v))
+					sb.WriteByte('"')
+				} else {
+					sb.WriteString(string(vbs))
+				}
+			} else {
 				sb.WriteByte('"')
-				sb.WriteString(fmt.Sprintf("%+v", v))
+				sb.WriteString(vStr)
 				sb.WriteByte('"')
-			} else {
-				sb.WriteString(string(vbs))
 			}
 			i = i + 2
 		}
@@ -191,29 +201,29 @@ func (l *DefaultLogger) Debug(msg string, keysAndValues ...interface{}) {
 	if DebugLevel < globalLogLevel {
 		return
 	}
-	l.log.Print(AssembleMsg(globalCallerDepth, "DEBUG", msg, nil, keysAndValues...))
+	l.log.Print(AssembleMsg(GlobalCallerDepth, "DEBUG", msg, nil, keysAndValues...))
 }
 
 func (l *DefaultLogger) Info(msg string, keysAndValues ...interface{}) {
 	if InfoLevel < globalLogLevel {
 		return
 	}
-	l.log.Print(AssembleMsg(globalCallerDepth, "INFO", msg, nil, keysAndValues...))
+	l.log.Print(AssembleMsg(GlobalCallerDepth, "INFO", msg, nil, keysAndValues...))
 }
 
 func (l *DefaultLogger) Warn(msg string, keysAndValues ...interface{}) {
 	if WarnLevel < globalLogLevel {
 		return
 	}
 
-	l.log.Print(AssembleMsg(globalCallerDepth, "WARNING", msg, nil, keysAndValues...))
+	l.log.Print(AssembleMsg(GlobalCallerDepth, "WARNING", msg, nil, keysAndValues...))
 }
 
 func (l *DefaultLogger) Error(err error, msg string, keysAndValues ...interface{}) {
 	if ErrorLevel < globalLogLevel {
 		return
 	}
-	l.log.Print(AssembleMsg(globalCallerDepth, "ERROR", msg, err, keysAndValues...))
+	l.log.Print(AssembleMsg(GlobalCallerDepth, "ERROR", msg, err, keysAndValues...))
 }
 
 func Debug(msg string, keysAndValues ...interface{}) {