From 3152581d0d30b54a09031500459d5604b8992c7e Mon Sep 17 00:00:00 2001 From: Kevin Wan Date: Fri, 8 Aug 2025 20:23:10 +0800 Subject: [PATCH] optimize: logging with fields (#5066) --- core/logx/logs.go | 37 ++------------- core/logx/logs_test.go | 103 +++++++++++++++++++++++++++++++++++++++++ core/logx/writer.go | 43 ++++++++++++++++- 3 files changed, 148 insertions(+), 35 deletions(-) diff --git a/core/logx/logs.go b/core/logx/logs.go index 447de86a1..404f47fab 100644 --- a/core/logx/logs.go +++ b/core/logx/logs.go @@ -10,7 +10,6 @@ import ( "runtime/debug" "sync" "sync/atomic" - "time" "github.com/zeromicro/go-zero/core/sysx" ) @@ -187,39 +186,9 @@ func Errorw(msg string, fields ...LogField) { // Field returns a LogField for the given key and value. func Field(key string, value any) LogField { - switch val := value.(type) { - case error: - return LogField{Key: key, Value: encodeError(val)} - case []error: - var errs []string - for _, err := range val { - errs = append(errs, encodeError(err)) - } - return LogField{Key: key, Value: errs} - case time.Duration: - return LogField{Key: key, Value: fmt.Sprint(val)} - case []time.Duration: - var durs []string - for _, dur := range val { - durs = append(durs, fmt.Sprint(dur)) - } - return LogField{Key: key, Value: durs} - case []time.Time: - var times []string - for _, t := range val { - times = append(times, fmt.Sprint(t)) - } - return LogField{Key: key, Value: times} - case fmt.Stringer: - return LogField{Key: key, Value: encodeStringer(val)} - case []fmt.Stringer: - var strs []string - for _, str := range val { - strs = append(strs, encodeStringer(str)) - } - return LogField{Key: key, Value: strs} - default: - return LogField{Key: key, Value: val} + return LogField{ + Key: key, + Value: value, } } diff --git a/core/logx/logs_test.go b/core/logx/logs_test.go index 2108c6c87..1c3c00de2 100644 --- a/core/logx/logs_test.go +++ b/core/logx/logs_test.go @@ -1,6 +1,7 @@ package logx import ( + "context" "encoding/json" "errors" "fmt" @@ -856,6 +857,95 @@ func TestWithKeepDays(t *testing.T) { assert.Equal(t, 1, opt.keepDays) } +func TestWithField_LogLevel(t *testing.T) { + tests := []struct { + name string + level uint32 + fn func(string, ...LogField) + count int32 + }{ + { + name: "debug/info", + level: DebugLevel, + fn: Infow, + count: 1, + }, + { + name: "info/error", + level: InfoLevel, + fn: Errorw, + count: 1, + }, + { + name: "info/info", + level: InfoLevel, + fn: Infow, + count: 1, + }, + { + name: "info/severe", + level: InfoLevel, + fn: Errorw, + count: 1, + }, + { + name: "error/info", + level: ErrorLevel, + fn: Infow, + count: 0, + }, + { + name: "error/debug", + level: ErrorLevel, + fn: Debugw, + count: 0, + }, + } + + for _, tt := range tests { + tt := tt + t.Run(tt.name, func(t *testing.T) { + olevel := atomic.LoadUint32(&logLevel) + SetLevel(tt.level) + defer SetLevel(olevel) + + var val countingStringer + tt.fn("hello there", Field("foo", &val)) + assert.Equal(t, tt.count, val.Count()) + }) + } +} + +func TestWithField_LogLevelWithContext(t *testing.T) { + t.Run("context more than once with info/info", func(t *testing.T) { + olevel := atomic.LoadUint32(&logLevel) + SetLevel(InfoLevel) + defer SetLevel(olevel) + + var val countingStringer + ctx := ContextWithFields(context.Background(), Field("foo", &val)) + logger := WithContext(ctx) + logger.Info("hello there") + logger.Info("hello there") + logger.Info("hello there") + assert.True(t, val.Count() > 0) + }) + + t.Run("context more than once with error/info", func(t *testing.T) { + olevel := atomic.LoadUint32(&logLevel) + SetLevel(ErrorLevel) + defer SetLevel(olevel) + + var val countingStringer + ctx := ContextWithFields(context.Background(), Field("foo", &val)) + logger := WithContext(ctx) + logger.Info("hello there") + logger.Info("hello there") + logger.Info("hello there") + assert.Equal(t, int32(0), val.Count()) + }) +} + func BenchmarkCopyByteSliceAppend(b *testing.B) { for i := 0; i < b.N; i++ { var buf []byte @@ -1054,3 +1144,16 @@ type panicStringer struct { func (s panicStringer) String() string { panic("panic") } + +type countingStringer struct { + count int32 +} + +func (s *countingStringer) Count() int32 { + return atomic.LoadInt32(&s.count) +} + +func (s *countingStringer) String() string { + atomic.AddInt32(&s.count, 1) + return "countingStringer" +} diff --git a/core/logx/writer.go b/core/logx/writer.go index 0e2ca9e8a..c71408746 100644 --- a/core/logx/writer.go +++ b/core/logx/writer.go @@ -10,6 +10,7 @@ import ( "runtime/debug" "sync" "sync/atomic" + "time" fatihcolor "github.com/fatih/color" "github.com/zeromicro/go-zero/core/color" @@ -380,7 +381,10 @@ func output(writer io.Writer, level string, val any, fields ...LogField) { // +3 for timestamp, level and content entry := make(logEntry, len(fields)+3) for _, field := range fields { - entry[field.Key] = maskSensitive(field.Value) + // mask sensitive data before processing types, + // in case field.Value is a sensitive type and also implemented fmt.Stringer. + mval := maskSensitive(field.Value) + entry[field.Key] = processFieldValue(mval) } switch atomic.LoadUint32(&encoding) { @@ -395,6 +399,43 @@ func output(writer io.Writer, level string, val any, fields ...LogField) { } } +func processFieldValue(value any) any { + switch val := value.(type) { + case error: + return encodeError(val) + case []error: + var errs []string + for _, err := range val { + errs = append(errs, encodeError(err)) + } + return errs + case time.Duration: + return fmt.Sprint(val) + case []time.Duration: + var durs []string + for _, dur := range val { + durs = append(durs, fmt.Sprint(dur)) + } + return durs + case []time.Time: + var times []string + for _, t := range val { + times = append(times, fmt.Sprint(t)) + } + return times + case fmt.Stringer: + return encodeStringer(val) + case []fmt.Stringer: + var strs []string + for _, str := range val { + strs = append(strs, encodeStringer(str)) + } + return strs + default: + return val + } +} + func wrapLevelWithColor(level string) string { var colour color.Color switch level {