From 350834cf33efe807ee7ddba385873fb0c9c1b4f3 Mon Sep 17 00:00:00 2001 From: kevin Date: Sat, 25 Jan 2025 23:28:37 +0800 Subject: [PATCH] chore: add more tests for logx/logc --- core/logc/logs.go | 38 ++++++--- core/logc/logs_test.go | 36 +++++++++ core/logx/logger.go | 12 ++- core/logx/logs.go | 41 +++++++--- core/logx/logs_test.go | 147 +++++++++++++++++++++++++++-------- core/logx/richlogger.go | 29 +++++-- core/logx/richlogger_test.go | 20 +++++ zrpc/server_test.go | 6 +- 8 files changed, 261 insertions(+), 68 deletions(-) diff --git a/core/logc/logs.go b/core/logc/logs.go index e3af5f8c6eb6..f690960e8680 100644 --- a/core/logc/logs.go +++ b/core/logc/logs.go @@ -37,16 +37,18 @@ func Debugf(ctx context.Context, format string, v ...interface{}) { getLogger(ctx).Debugf(format, v...) } +// Debugfn writes fn result into access log. +// This is useful when the function is expensive to compute, +// and we want to log it only when necessary. +func Debugfn(ctx context.Context, fn func() any) { + getLogger(ctx).Debugfn(fn) +} + // Debugv writes v into access log with json content. func Debugv(ctx context.Context, v interface{}) { getLogger(ctx).Debugv(v) } -// Debugfn writes fn result into access log. -func Debugfn(ctx context.Context, fn func() string) { - getLogger(ctx).Debugfn(fn) -} - // Debugw writes msg along with fields into the access log. func Debugw(ctx context.Context, msg string, fields ...LogField) { getLogger(ctx).Debugw(msg, fields...) @@ -62,6 +64,13 @@ func Errorf(ctx context.Context, format string, v ...any) { getLogger(ctx).Errorf(fmt.Errorf(format, v...).Error()) } +// Errorfn writes fn result into error log. +// This is useful when the function is expensive to compute, +// and we want to log it only when necessary. +func Errorfn(ctx context.Context, fn func() any) { + getLogger(ctx).Errorfn(fn) +} + // Errorv writes v into error log with json content. // No call stack attached, because not elegant to pack the messages. func Errorv(ctx context.Context, v any) { @@ -88,16 +97,18 @@ func Infof(ctx context.Context, format string, v ...any) { getLogger(ctx).Infof(format, v...) } +// Infofn writes fn result into access log. +// This is useful when the function is expensive to compute, +// and we want to log it only when necessary. +func Infofn(ctx context.Context, fn func() any) { + getLogger(ctx).Infofn(fn) +} + // Infov writes v into access log with json content. func Infov(ctx context.Context, v any) { getLogger(ctx).Infov(v) } -// Infofn writes fn result into access log. -func Infofn(ctx context.Context, fn func() string) { - getLogger(ctx).Infofn(fn) -} - // Infow writes msg along with fields into the access log. func Infow(ctx context.Context, msg string, fields ...LogField) { getLogger(ctx).Infow(msg, fields...) @@ -137,6 +148,13 @@ func Slowf(ctx context.Context, format string, v ...any) { getLogger(ctx).Slowf(format, v...) } +// Slowfn writes fn result into slow log. +// This is useful when the function is expensive to compute, +// and we want to log it only when necessary. +func Slowfn(ctx context.Context, fn func() any) { + getLogger(ctx).Slowfn(fn) +} + // Slowv writes v into slow log with json content. func Slowv(ctx context.Context, v any) { getLogger(ctx).Slowv(v) diff --git a/core/logc/logs_test.go b/core/logc/logs_test.go index 3ee986423617..8bd3c51a755c 100644 --- a/core/logc/logs_test.go +++ b/core/logc/logs_test.go @@ -49,6 +49,15 @@ func TestErrorf(t *testing.T) { assert.True(t, strings.Contains(buf.String(), fmt.Sprintf("%s:%d", file, line+1))) } +func TestErrorfn(t *testing.T) { + buf := logtest.NewCollector(t) + file, line := getFileLine() + Errorfn(context.Background(), func() any { + return fmt.Sprintf("foo %s", "bar") + }) + assert.True(t, strings.Contains(buf.String(), fmt.Sprintf("%s:%d", file, line+1))) +} + func TestErrorv(t *testing.T) { buf := logtest.NewCollector(t) file, line := getFileLine() @@ -77,6 +86,15 @@ func TestInfof(t *testing.T) { assert.True(t, strings.Contains(buf.String(), fmt.Sprintf("%s:%d", file, line+1))) } +func TestInfofn(t *testing.T) { + buf := logtest.NewCollector(t) + file, line := getFileLine() + Infofn(context.Background(), func() any { + return fmt.Sprintf("foo %s", "bar") + }) + assert.True(t, strings.Contains(buf.String(), fmt.Sprintf("%s:%d", file, line+1))) +} + func TestInfov(t *testing.T) { buf := logtest.NewCollector(t) file, line := getFileLine() @@ -105,6 +123,15 @@ func TestDebugf(t *testing.T) { assert.True(t, strings.Contains(buf.String(), fmt.Sprintf("%s:%d", file, line+1))) } +func TestDebugfn(t *testing.T) { + buf := logtest.NewCollector(t) + file, line := getFileLine() + Debugfn(context.Background(), func() any { + return fmt.Sprintf("foo %s", "bar") + }) + assert.True(t, strings.Contains(buf.String(), fmt.Sprintf("%s:%d", file, line+1))) +} + func TestDebugv(t *testing.T) { buf := logtest.NewCollector(t) file, line := getFileLine() @@ -148,6 +175,15 @@ func TestSlowf(t *testing.T) { assert.True(t, strings.Contains(buf.String(), fmt.Sprintf("%s:%d", file, line+1)), buf.String()) } +func TestSlowfn(t *testing.T) { + buf := logtest.NewCollector(t) + file, line := getFileLine() + Slowfn(context.Background(), func() any { + return fmt.Sprintf("foo %s", "bar") + }) + assert.True(t, strings.Contains(buf.String(), fmt.Sprintf("%s:%d", file, line+1)), buf.String()) +} + func TestSlowv(t *testing.T) { buf := logtest.NewCollector(t) file, line := getFileLine() diff --git a/core/logx/logger.go b/core/logx/logger.go index ca236d1108b7..8f8c1ec28c93 100644 --- a/core/logx/logger.go +++ b/core/logx/logger.go @@ -11,16 +11,18 @@ type Logger interface { Debug(...any) // Debugf logs a message at debug level. Debugf(string, ...any) + // Debugfn logs a message at debug level. + Debugfn(func() any) // Debugv logs a message at debug level. Debugv(any) - // Debugfn logs a message at debug level. - Debugfn(func() string) // Debugw logs a message at debug level. Debugw(string, ...LogField) // Error logs a message at error level. Error(...any) // Errorf logs a message at error level. Errorf(string, ...any) + // Errorfn logs a message at error level. + Errorfn(func() any) // Errorv logs a message at error level. Errorv(any) // Errorw logs a message at error level. @@ -29,16 +31,18 @@ type Logger interface { Info(...any) // Infof logs a message at info level. Infof(string, ...any) + // Infofn logs a message at info level. + Infofn(func() any) // Infov logs a message at info level. Infov(any) - // Infofn logs a message at info level. - Infofn(func() string) // Infow logs a message at info level. Infow(string, ...LogField) // Slow logs a message at slow level. Slow(...any) // Slowf logs a message at slow level. Slowf(string, ...any) + // Slowfn logs a message at slow level. + Slowfn(func() any) // Slowv logs a message at slow level. Slowv(any) // Sloww logs a message at slow level. diff --git a/core/logx/logs.go b/core/logx/logs.go index 631c413f8010..cc707bb45c0c 100644 --- a/core/logx/logs.go +++ b/core/logx/logs.go @@ -100,17 +100,18 @@ func Debugf(format string, v ...any) { } } -// Debugv writes v into access log with json content. -func Debugv(v any) { +// Debugfn writes function result into access log if debug level enabled. +// This is useful when the function is expensive to call and debug level disabled. +func Debugfn(fn func() any) { if shallLog(DebugLevel) { - writeDebug(v) + writeDebug(fn()) } } -// Debugfn writes function result into access log. -func Debugfn(fn func() string) { +// Debugv writes v into access log with json content. +func Debugv(v any) { if shallLog(DebugLevel) { - writeDebug(fn()) + writeDebug(v) } } @@ -146,6 +147,13 @@ func Errorf(format string, v ...any) { } } +// Errorfn writes function result into error log. +func Errorfn(fn func() any) { + if shallLog(ErrorLevel) { + writeError(fn()) + } +} + // ErrorStack writes v along with call stack into error log. func ErrorStack(v ...any) { if shallLog(ErrorLevel) { @@ -229,17 +237,18 @@ func Infof(format string, v ...any) { } } -// Infov writes v into access log with json content. -func Infov(v any) { +// Infofn writes function result into access log. +// This is useful when the function is expensive to call and info level disabled. +func Infofn(fn func() any) { if shallLog(InfoLevel) { - writeInfo(v) + writeInfo(fn()) } } -// Infofn writes function result into access log. -func Infofn(fn func() string) { +// Infov writes v into access log with json content. +func Infov(v any) { if shallLog(InfoLevel) { - writeInfo(fn()) + writeInfo(v) } } @@ -362,6 +371,14 @@ func Slowf(format string, v ...any) { } } +// Slowfn writes function result into slow log. +// This is useful when the function is expensive to call and slow level disabled. +func Slowfn(fn func() any) { + if shallLog(ErrorLevel) { + writeSlow(fn()) + } +} + // Slowv writes v into slow log with json content. func Slowv(v any) { if shallLog(ErrorLevel) { diff --git a/core/logx/logs_test.go b/core/logx/logs_test.go index 35a609a47830..2108c6c877b8 100644 --- a/core/logx/logs_test.go +++ b/core/logx/logs_test.go @@ -248,35 +248,42 @@ func TestStructedLogDebugf(t *testing.T) { }) } -func TestStructedLogDebugv(t *testing.T) { - w := new(mockWriter) - old := writer.Swap(w) - defer writer.Store(old) +func TestStructedLogDebugfn(t *testing.T) { + t.Run("debugfn with output", func(t *testing.T) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLog(t, levelDebug, w, func(v ...any) { + Debugfn(func() any { + return fmt.Sprint(v...) + }) + }) + }) - doTestStructedLog(t, levelDebug, w, func(v ...any) { - Debugv(fmt.Sprint(v...)) + t.Run("debugfn without output", func(t *testing.T) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLogEmpty(t, w, InfoLevel, func(v ...any) { + Debugfn(func() any { + return fmt.Sprint(v...) + }) + }) }) } -func TestStructedLogDebugfn(t *testing.T) { + +func TestStructedLogDebugv(t *testing.T) { w := new(mockWriter) old := writer.Swap(w) defer writer.Store(old) + doTestStructedLog(t, levelDebug, w, func(v ...any) { - Debugfn(func() string { - return fmt.Sprint(v...) - }) - }) -} -func TestDebugfnWithInfoLevel(t *testing.T) { - called := false - SetLevel(InfoLevel) - defer SetLevel(DebugLevel) - Debugfn(func() string { - called = true - return "long time log" + Debugv(fmt.Sprint(v...)) }) - assert.False(t, called) } + func TestStructedLogDebugw(t *testing.T) { w := new(mockWriter) old := writer.Swap(w) @@ -307,6 +314,32 @@ func TestStructedLogErrorf(t *testing.T) { }) } +func TestStructedLogErrorfn(t *testing.T) { + t.Run("errorfn with output", func(t *testing.T) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLog(t, levelError, w, func(v ...any) { + Errorfn(func() any { + return fmt.Sprint(v...) + }) + }) + }) + + t.Run("errorfn without output", func(t *testing.T) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLogEmpty(t, w, SevereLevel, func(v ...any) { + Errorfn(func() any { + return fmt.Sprint(v...) + }) + }) + }) +} + func TestStructedLogErrorv(t *testing.T) { w := new(mockWriter) old := writer.Swap(w) @@ -347,6 +380,32 @@ func TestStructedLogInfof(t *testing.T) { }) } +func TestStructedInfofn(t *testing.T) { + t.Run("infofn with output", func(t *testing.T) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLog(t, levelInfo, w, func(v ...any) { + Infofn(func() any { + return fmt.Sprint(v...) + }) + }) + }) + + t.Run("infofn without output", func(t *testing.T) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLogEmpty(t, w, ErrorLevel, func(v ...any) { + Infofn(func() any { + return fmt.Sprint(v...) + }) + }) + }) +} + func TestStructedLogInfov(t *testing.T) { w := new(mockWriter) old := writer.Swap(w) @@ -469,22 +528,12 @@ func TestStructedLogInfoConsoleText(t *testing.T) { Info(fmt.Sprint(v...)) }) } -func TestStructedInfofn(t *testing.T) { - w := new(mockWriter) - old := writer.Swap(w) - defer writer.Store(old) - doTestStructedLog(t, levelInfo, w, func(v ...any) { - Infofn(func() string { - return fmt.Sprint(v...) - }) - }) -} func TestInfofnWithErrorLevel(t *testing.T) { called := false SetLevel(ErrorLevel) defer SetLevel(DebugLevel) - Infofn(func() string { + Infofn(func() any { called = true return "info log" }) @@ -511,6 +560,32 @@ func TestStructedLogSlowf(t *testing.T) { }) } +func TestStructedLogSlowfn(t *testing.T) { + t.Run("slowfn with output", func(t *testing.T) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLog(t, levelSlow, w, func(v ...any) { + Slowfn(func() any { + return fmt.Sprint(v...) + }) + }) + }) + + t.Run("slowfn without output", func(t *testing.T) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLogEmpty(t, w, SevereLevel, func(v ...any) { + Slowfn(func() any { + return fmt.Sprint(v...) + }) + }) + }) +} + func TestStructedLogSlowv(t *testing.T) { w := new(mockWriter) old := writer.Swap(w) @@ -887,6 +962,16 @@ func doTestStructedLogConsole(t *testing.T, w *mockWriter, write func(...any)) { assert.True(t, strings.Contains(w.String(), message)) } +func doTestStructedLogEmpty(t *testing.T, w *mockWriter, level uint32, write func(...any)) { + olevel := atomic.LoadUint32(&logLevel) + SetLevel(level) + defer SetLevel(olevel) + + const message = "hello there" + write(message) + assert.Empty(t, w.String()) +} + func testSetLevelTwiceWithMode(t *testing.T, mode string, w *mockWriter) { writer.Store(nil) SetUp(LogConf{ diff --git a/core/logx/richlogger.go b/core/logx/richlogger.go index 8af6bf999020..17f9eb23b216 100644 --- a/core/logx/richlogger.go +++ b/core/logx/richlogger.go @@ -52,14 +52,15 @@ func (l *richLogger) Debugf(format string, v ...any) { } } -func (l *richLogger) Debugv(v any) { +func (l *richLogger) Debugfn(fn func() any) { if shallLog(DebugLevel) { - l.debug(v) + l.debug(fn()) } } -func (l *richLogger) Debugfn(fn func() string) { + +func (l *richLogger) Debugv(v any) { if shallLog(DebugLevel) { - l.debug(fn()) + l.debug(v) } } @@ -81,6 +82,12 @@ func (l *richLogger) Errorf(format string, v ...any) { } } +func (l *richLogger) Errorfn(fn func() any) { + if shallLog(ErrorLevel) { + l.err(fn()) + } +} + func (l *richLogger) Errorv(v any) { if shallLog(ErrorLevel) { l.err(v) @@ -105,15 +112,15 @@ func (l *richLogger) Infof(format string, v ...any) { } } -func (l *richLogger) Infov(v any) { +func (l *richLogger) Infofn(fn func() any) { if shallLog(InfoLevel) { - l.info(v) + l.info(fn()) } } -func (l *richLogger) Infofn(fn func() string) { +func (l *richLogger) Infov(v any) { if shallLog(InfoLevel) { - l.info(fn()) + l.info(v) } } @@ -135,6 +142,12 @@ func (l *richLogger) Slowf(format string, v ...any) { } } +func (l *richLogger) Slowfn(fn func() any) { + if shallLog(ErrorLevel) { + l.slow(fn()) + } +} + func (l *richLogger) Slowv(v any) { if shallLog(ErrorLevel) { l.slow(v) diff --git a/core/logx/richlogger_test.go b/core/logx/richlogger_test.go index 52194d432916..8d6bfb44310d 100644 --- a/core/logx/richlogger_test.go +++ b/core/logx/richlogger_test.go @@ -63,6 +63,11 @@ func TestTraceDebug(t *testing.T) { l.WithDuration(time.Second).Debugf(testlog) validate(t, w.String(), true, true) w.Reset() + l.WithDuration(time.Second).Debugfn(func() any { + return testlog + }) + validate(t, w.String(), true, true) + w.Reset() l.WithDuration(time.Second).Debugv(testlog) validate(t, w.String(), true, true) w.Reset() @@ -103,6 +108,11 @@ func TestTraceError(t *testing.T) { l.WithDuration(time.Second).Errorf(testlog) validate(t, w.String(), true, true) w.Reset() + l.WithDuration(time.Second).Errorfn(func() any { + return testlog + }) + validate(t, w.String(), true, true) + w.Reset() l.WithDuration(time.Second).Errorv(testlog) validate(t, w.String(), true, true) w.Reset() @@ -140,6 +150,11 @@ func TestTraceInfo(t *testing.T) { l.WithDuration(time.Second).Infof(testlog) validate(t, w.String(), true, true) w.Reset() + l.WithDuration(time.Second).Infofn(func() any { + return testlog + }) + validate(t, w.String(), true, true) + w.Reset() l.WithDuration(time.Second).Infov(testlog) validate(t, w.String(), true, true) w.Reset() @@ -213,6 +228,11 @@ func TestTraceSlow(t *testing.T) { l.WithDuration(time.Second).Slowf(testlog) validate(t, w.String(), true, true) w.Reset() + l.WithDuration(time.Second).Slowfn(func() any { + return testlog + }) + validate(t, w.String(), true, true) + w.Reset() l.WithDuration(time.Second).Slowv(testlog) validate(t, w.String(), true, true) w.Reset() diff --git a/zrpc/server_test.go b/zrpc/server_test.go index e42e379a6cd1..2c9bf57dff18 100644 --- a/zrpc/server_test.go +++ b/zrpc/server_test.go @@ -27,7 +27,7 @@ func TestServer(t *testing.T) { Mode: "console", }, }, - ListenOn: "localhost:8080", + ListenOn: "localhost:0", Etcd: discov.EtcdConf{}, Auth: false, Redis: redis.RedisKeyConf{}, @@ -64,7 +64,7 @@ func TestServerError(t *testing.T) { Mode: "console", }, }, - ListenOn: "localhost:8080", + ListenOn: "localhost:0", Etcd: discov.EtcdConf{ Hosts: []string{"localhost"}, }, @@ -91,7 +91,7 @@ func TestServer_HasEtcd(t *testing.T) { Mode: "console", }, }, - ListenOn: "localhost:8080", + ListenOn: "localhost:0", Etcd: discov.EtcdConf{ Hosts: []string{"notexist"}, Key: "any",