From 21ac47203798175fff008953746b509e862ebb7d Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Fri, 22 Nov 2024 15:20:20 +0200 Subject: [PATCH 01/12] handler_test: restructure test Move the test cases to the bottom of the file so that we can add more tests without the results (line number) of the call-site test changing. --- v2/handler_test.go | 302 +++++++++++++++++++++++---------------------- 1 file changed, 152 insertions(+), 150 deletions(-) diff --git a/v2/handler_test.go b/v2/handler_test.go index dfdceb0..0cbeb17 100644 --- a/v2/handler_test.go +++ b/v2/handler_test.go @@ -4,125 +4,149 @@ import ( "bytes" "context" "errors" - "github.com/btcsuite/btclog" "io" "testing" "time" + + "github.com/btcsuite/btclog" ) // TestDefaultHandler tests that the DefaultHandler's output looks as expected. func TestDefaultHandler(t *testing.T) { t.Parallel() - timeSource := func() time.Time { - return time.Unix(100, 100) + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + var buf bytes.Buffer + handler := test.handlerConstructor(&buf) + handler.SetLevel(test.level) + + if handler.Level() != test.level { + t.Fatalf("Incorrect level. Expected %s, "+ + "got %s", test.level, handler.Level()) + } + + test.logFunc(NewSLogger(handler)) + + if buf.String() != test.expectedLog { + t.Fatalf("Log result mismatch. Expected "+ + "\n\"%s\", got \n\"%s\"", + test.expectedLog, buf.Bytes()) + } + }) } +} - tests := []struct { - name string - handlerConstructor func(w io.Writer) Handler - level btclog.Level - logFunc func(log Logger) - expectedLog string - }{ - { - name: "Basic calls and levels", - handlerConstructor: func(w io.Writer) Handler { - return NewDefaultHandler( - w, WithTimeSource(timeSource), - ) - }, - level: LevelDebug, - logFunc: func(log Logger) { - log.Info("Test Basic Log") - log.Debugf("Test basic log with %s", "format") - log.Trace("Log should not appear due to level") - }, - expectedLog: `1970-01-01 02:01:40.000 [INF]: Test Basic Log -1970-01-01 02:01:40.000 [DBG]: Test basic log with format +var timeSource = func() time.Time { + return time.Date(2009, time.January, 3, 12, 0, 0, 0, time.UTC) + +} + +var tests = []struct { + name string + handlerConstructor func(w io.Writer) Handler + level btclog.Level + logFunc func(log Logger) + expectedLog string +}{ + { + name: "Basic calls and levels", + handlerConstructor: func(w io.Writer) Handler { + return NewDefaultHandler( + w, WithTimeSource(timeSource), + ) + }, + level: LevelDebug, + logFunc: func(log Logger) { + log.Info("Test Basic Log") + log.Debugf("Test basic log with %s", "format") + log.Trace("Log should not appear due to level") + }, + expectedLog: `2009-01-03 12:00:00.000 [INF]: Test Basic Log +2009-01-03 12:00:00.000 [DBG]: Test basic log with format `, + }, + { + name: "Call site", + handlerConstructor: func(w io.Writer) Handler { + return NewDefaultHandler( + w, WithNoTimestamp(), + WithCallSiteSkipDepth(7), + WithCallerFlags(Lshortfile), + ) + }, + level: LevelInfo, + logFunc: func(log Logger) { + log.Info("Test Basic Log") }, - { - name: "Call site", - handlerConstructor: func(w io.Writer) Handler { - return NewDefaultHandler( - w, WithNoTimestamp(), - WithCallSiteSkipDepth(7), - WithCallerFlags(Lshortfile), - ) - }, - level: LevelInfo, - logFunc: func(log Logger) { - log.Info("Test Basic Log") - }, - expectedLog: `[INF] handler_test.go:196: Test Basic Log + expectedLog: `[INF] handler_test.go:29: Test Basic Log `, + }, + { + name: "Sub-system tag", + handlerConstructor: func(w io.Writer) Handler { + h := NewDefaultHandler(w, WithNoTimestamp()) + return h.SubSystem("SUBS") + }, + level: LevelInfo, + logFunc: func(log Logger) { + log.Info("Test Basic Log") }, - { - name: "Sub-system tag", - handlerConstructor: func(w io.Writer) Handler { - h := NewDefaultHandler(w, WithNoTimestamp()) - return h.SubSystem("SUBS") - }, - level: LevelInfo, - logFunc: func(log Logger) { - log.Info("Test Basic Log") - }, - expectedLog: `[INF] SUBS: Test Basic Log + expectedLog: `[INF] SUBS: Test Basic Log `, + }, + { + name: "Test all levels", + handlerConstructor: func(w io.Writer) Handler { + return NewDefaultHandler(w, WithNoTimestamp()) }, - { - name: "Test all levels", - handlerConstructor: func(w io.Writer) Handler { - return NewDefaultHandler(w, WithNoTimestamp()) - }, - level: LevelTrace, - logFunc: func(log Logger) { - log.Trace("Trace") - log.Debug("Debug") - log.Info("Info") - log.Warn("Warn") - log.Error("Error") - log.Critical("Critical") - }, - expectedLog: `[TRC]: Trace + level: LevelTrace, + logFunc: func(log Logger) { + log.Trace("Trace") + log.Debug("Debug") + log.Info("Info") + log.Warn("Warn") + log.Error("Error") + log.Critical("Critical") + }, + expectedLog: `[TRC]: Trace [DBG]: Debug [INF]: Info [WRN]: Warn [ERR]: Error [CRT]: Critical `, + }, + { + name: "Structured Logs", + handlerConstructor: func(w io.Writer) Handler { + return NewDefaultHandler(w, WithNoTimestamp()) + }, + level: LevelInfo, + logFunc: func(log Logger) { + ctx := context.Background() + log.InfoS(ctx, "No attributes") + log.InfoS(ctx, "Single word attribute", "key", "value") + log.InfoS(ctx, "Multi word string value", "key with spaces", "value") + log.InfoS(ctx, "Number attribute", "key", 5) + log.InfoS(ctx, "Bad key", "key") + + type b struct { + name string + age int + address *string + } + + var c *b + log.InfoS(ctx, "Nil pointer value", "key", c) + + c = &b{name: "Bob", age: 5} + log.InfoS(ctx, "Struct values", "key", c) + + ctx = WithCtx(ctx, "request_id", 5, "user_name", "alice") + log.InfoS(ctx, "Test context attributes", "key", "value") }, - { - name: "Structured Logs", - handlerConstructor: func(w io.Writer) Handler { - return NewDefaultHandler(w, WithNoTimestamp()) - }, - level: LevelInfo, - logFunc: func(log Logger) { - ctx := context.Background() - log.InfoS(ctx, "No attributes") - log.InfoS(ctx, "Single word attribute", "key", "value") - log.InfoS(ctx, "Multi word string value", "key with spaces", "value") - log.InfoS(ctx, "Number attribute", "key", 5) - log.InfoS(ctx, "Bad key", "key") - - type b struct { - name string - age int - address *string - } - - var c *b - log.InfoS(ctx, "Nil pointer value", "key", c) - - c = &b{name: "Bob", age: 5} - log.InfoS(ctx, "Struct values", "key", c) - - ctx = WithCtx(ctx, "request_id", 5, "user_name", "alice") - log.InfoS(ctx, "Test context attributes", "key", "value") - }, - expectedLog: `[INF]: No attributes + expectedLog: `[INF]: No attributes [INF]: Single word attribute key=value [INF]: Multi word string value "key with spaces"=value [INF]: Number attribute key=5 @@ -131,39 +155,39 @@ func TestDefaultHandler(t *testing.T) { [INF]: Struct values key="&{name:Bob age:5 address:}" [INF]: Test context attributes request_id=5 user_name=alice key=value `, + }, + { + name: "Error logs", + handlerConstructor: func(w io.Writer) Handler { + return NewDefaultHandler(w, WithNoTimestamp()) }, - { - name: "Error logs", - handlerConstructor: func(w io.Writer) Handler { - return NewDefaultHandler(w, WithNoTimestamp()) - }, - level: LevelInfo, - logFunc: func(log Logger) { - log.Error("Error string") - log.Errorf("Error formatted string") - - ctx := context.Background() - log.ErrorS(ctx, "Structured error log with nil error", nil) - log.ErrorS(ctx, "Structured error with non-nil error", errors.New("oh no")) - log.ErrorS(ctx, "Structured error with attributes", errors.New("oh no"), "key", "value") - - log.Warn("Warning string") - log.Warnf("Warning formatted string") - - ctx = context.Background() - log.WarnS(ctx, "Structured warning log with nil error", nil) - log.WarnS(ctx, "Structured warning with non-nil error", errors.New("oh no")) - log.WarnS(ctx, "Structured warning with attributes", errors.New("oh no"), "key", "value") - - log.Critical("Critical string") - log.Criticalf("Critical formatted string") - - ctx = context.Background() - log.CriticalS(ctx, "Structured critical log with nil error", nil) - log.CriticalS(ctx, "Structured critical with non-nil error", errors.New("oh no")) - log.CriticalS(ctx, "Structured critical with attributes", errors.New("oh no"), "key", "value") - }, - expectedLog: `[ERR]: Error string + level: LevelInfo, + logFunc: func(log Logger) { + log.Error("Error string") + log.Errorf("Error formatted string") + + ctx := context.Background() + log.ErrorS(ctx, "Structured error log with nil error", nil) + log.ErrorS(ctx, "Structured error with non-nil error", errors.New("oh no")) + log.ErrorS(ctx, "Structured error with attributes", errors.New("oh no"), "key", "value") + + log.Warn("Warning string") + log.Warnf("Warning formatted string") + + ctx = context.Background() + log.WarnS(ctx, "Structured warning log with nil error", nil) + log.WarnS(ctx, "Structured warning with non-nil error", errors.New("oh no")) + log.WarnS(ctx, "Structured warning with attributes", errors.New("oh no"), "key", "value") + + log.Critical("Critical string") + log.Criticalf("Critical formatted string") + + ctx = context.Background() + log.CriticalS(ctx, "Structured critical log with nil error", nil) + log.CriticalS(ctx, "Structured critical with non-nil error", errors.New("oh no")) + log.CriticalS(ctx, "Structured critical with attributes", errors.New("oh no"), "key", "value") + }, + expectedLog: `[ERR]: Error string [ERR]: Error formatted string [ERR]: Structured error log with nil error [ERR]: Structured error with non-nil error err="oh no" @@ -179,27 +203,5 @@ func TestDefaultHandler(t *testing.T) { [CRT]: Structured critical with non-nil error err="oh no" [CRT]: Structured critical with attributes err="oh no" key=value `, - }, - } - - for _, test := range tests { - t.Run(test.name, func(t *testing.T) { - var buf bytes.Buffer - handler := test.handlerConstructor(&buf) - handler.SetLevel(test.level) - - if handler.Level() != test.level { - t.Fatalf("Incorrect level. Expected %s, "+ - "got %s", test.level, handler.Level()) - } - - test.logFunc(NewSLogger(handler)) - - if string(buf.Bytes()) != test.expectedLog { - t.Fatalf("Log result mismatch. Expected "+ - "\n\"%s\", got \n\"%s\"", - test.expectedLog, buf.Bytes()) - } - }) - } + }, } From c9d039d159929bd25cc68544213c45fc352a5049 Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Mon, 25 Nov 2024 10:00:33 +0200 Subject: [PATCH 02/12] attrs: add Hex6 helper Like the Hex helper, this helper prints a byte array in hex form but this one prints a maximum of 6 bytes. --- v2/attrs.go | 14 +++++++++++--- v2/handler_test.go | 23 +++++++++++++++++++++++ 2 files changed, 34 insertions(+), 3 deletions(-) diff --git a/v2/attrs.go b/v2/attrs.go index 4aee922..9a577e8 100644 --- a/v2/attrs.go +++ b/v2/attrs.go @@ -6,11 +6,19 @@ import ( "log/slog" ) -// Hex is a convenience function for a hex-encoded log attributes. +// Hex is a convenience function for hex-encoded log attributes. func Hex(key string, value []byte) slog.Attr { - h := hex.EncodeToString(value) + return slog.String(key, hex.EncodeToString(value)) +} + +// Hex6 is a convenience function for hex-encoded log attributes which prints +// a maximum of 6 bytes. +func Hex6(key string, value []byte) slog.Attr { + if len(value) <= 6 { + return slog.String(key, hex.EncodeToString(value)) + } - return slog.String(key, h) + return slog.String(key, hex.EncodeToString(value[:6])) } type attrsKey struct{} diff --git a/v2/handler_test.go b/v2/handler_test.go index 0cbeb17..f24a439 100644 --- a/v2/handler_test.go +++ b/v2/handler_test.go @@ -202,6 +202,29 @@ var tests = []struct { [CRT]: Structured critical log with nil error [CRT]: Structured critical with non-nil error err="oh no" [CRT]: Structured critical with attributes err="oh no" key=value +`, + }, + { + name: "Slog Helpers", + handlerConstructor: func(w io.Writer) Handler { + return NewDefaultHandler(w, WithNoTimestamp()) + }, + level: LevelInfo, + logFunc: func(log Logger) { + ctx := context.Background() + log.InfoS(ctx, "msg", Hex("hex_val", []byte{ + 0x01, 0x02, 0x03, 0x04, 0x05, 0x06, 0x07, 0x08, + })) + log.InfoS(ctx, "msg", Hex6("hex_val", []byte{ + 0x01, 0x02, + })) + log.InfoS(ctx, "msg", Hex6("hex_val", []byte{ + 0x01, 0x02, 0x03, 0x04, 0x05, 0x06, 0x07, 0x08, + })) + }, + expectedLog: `[INF]: msg hex_val=0102030405060708 +[INF]: msg hex_val=0102 +[INF]: msg hex_val=010203040506 `, }, } From 8efaf8e19d9f38115f07e4469b9e5c8bd4ec243b Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Fri, 22 Nov 2024 15:47:44 +0200 Subject: [PATCH 03/12] attrs+closure: add Closure methods Along with helpers to convert closures into slog Attributes. --- v2/attrs.go | 23 +++++++++++++++++++++++ v2/closure.go | 35 +++++++++++++++++++++++++++++++++++ v2/handler_test.go | 40 +++++++++++++++++++++++++++++++--------- 3 files changed, 89 insertions(+), 9 deletions(-) create mode 100644 v2/closure.go diff --git a/v2/attrs.go b/v2/attrs.go index 9a577e8..d9af6b4 100644 --- a/v2/attrs.go +++ b/v2/attrs.go @@ -21,6 +21,29 @@ func Hex6(key string, value []byte) slog.Attr { return slog.String(key, hex.EncodeToString(value[:6])) } +// Fmt returns a slog.Attr with the formatted message which is only computed +// when needed. +// +// Example usage: +// +// log.InfoS(ctx, "Main message", Fmt("key", "%.12f", 3.241)) +func Fmt(key string, msg string, params ...any) slog.Attr { + return slog.Any(key, Sprintf(msg, params...)) +} + +// ClosureAttr returns an slog attribute that will only perform the given +// logging operation if the corresponding log level is enabled. +// +// Example usage: +// +// log.InfoS(ctx, "msg", ClosureAttr("key", func() string { +// // Replace with an expensive string computation call. +// return "expensive string" +// })) +func ClosureAttr(key string, compute func() string) slog.Attr { + return slog.Any(key, NewClosure(compute)) +} + type attrsKey struct{} // WithCtx returns a copy of the context with which the logging attributes are diff --git a/v2/closure.go b/v2/closure.go new file mode 100644 index 0000000..a460bc4 --- /dev/null +++ b/v2/closure.go @@ -0,0 +1,35 @@ +package btclog + +import ( + "fmt" +) + +// Closure is used to provide a closure over expensive logging operations so +// that they don't have to be performed when the logging level doesn't warrant +// it. +type Closure func() string + +// String invokes the underlying function and returns the result. +func (c Closure) String() string { + return c() +} + +// NewClosure returns a new closure over a function that returns a string +// which itself provides a Stringer interface so that it can be used with the +// logging system. +func NewClosure(compute func() string) Closure { + return compute +} + +// Sprintf returns a fmt.Stringer that will lazily compute the string when +// needed. This is useful when the string is expensive to compute and may not be +// needed due to the log level being used. +// +// Example usage: +// +// log.InfoS(ctx, "msg", "key", Sprintf("%.12f", 3.241)) +func Sprintf(msg string, params ...any) fmt.Stringer { + return NewClosure(func() string { + return fmt.Sprintf(msg, params...) + }) +} diff --git a/v2/handler_test.go b/v2/handler_test.go index f24a439..a3a7467 100644 --- a/v2/handler_test.go +++ b/v2/handler_test.go @@ -26,7 +26,7 @@ func TestDefaultHandler(t *testing.T) { "got %s", test.level, handler.Level()) } - test.logFunc(NewSLogger(handler)) + test.logFunc(t, NewSLogger(handler)) if buf.String() != test.expectedLog { t.Fatalf("Log result mismatch. Expected "+ @@ -46,7 +46,7 @@ var tests = []struct { name string handlerConstructor func(w io.Writer) Handler level btclog.Level - logFunc func(log Logger) + logFunc func(t *testing.T, log Logger) expectedLog string }{ { @@ -57,7 +57,7 @@ var tests = []struct { ) }, level: LevelDebug, - logFunc: func(log Logger) { + logFunc: func(t *testing.T, log Logger) { log.Info("Test Basic Log") log.Debugf("Test basic log with %s", "format") log.Trace("Log should not appear due to level") @@ -76,7 +76,7 @@ var tests = []struct { ) }, level: LevelInfo, - logFunc: func(log Logger) { + logFunc: func(t *testing.T, log Logger) { log.Info("Test Basic Log") }, expectedLog: `[INF] handler_test.go:29: Test Basic Log @@ -89,7 +89,7 @@ var tests = []struct { return h.SubSystem("SUBS") }, level: LevelInfo, - logFunc: func(log Logger) { + logFunc: func(t *testing.T, log Logger) { log.Info("Test Basic Log") }, expectedLog: `[INF] SUBS: Test Basic Log @@ -101,7 +101,7 @@ var tests = []struct { return NewDefaultHandler(w, WithNoTimestamp()) }, level: LevelTrace, - logFunc: func(log Logger) { + logFunc: func(t *testing.T, log Logger) { log.Trace("Trace") log.Debug("Debug") log.Info("Info") @@ -123,7 +123,7 @@ var tests = []struct { return NewDefaultHandler(w, WithNoTimestamp()) }, level: LevelInfo, - logFunc: func(log Logger) { + logFunc: func(t *testing.T, log Logger) { ctx := context.Background() log.InfoS(ctx, "No attributes") log.InfoS(ctx, "Single word attribute", "key", "value") @@ -162,7 +162,7 @@ var tests = []struct { return NewDefaultHandler(w, WithNoTimestamp()) }, level: LevelInfo, - logFunc: func(log Logger) { + logFunc: func(t *testing.T, log Logger) { log.Error("Error string") log.Errorf("Error formatted string") @@ -210,7 +210,7 @@ var tests = []struct { return NewDefaultHandler(w, WithNoTimestamp()) }, level: LevelInfo, - logFunc: func(log Logger) { + logFunc: func(t *testing.T, log Logger) { ctx := context.Background() log.InfoS(ctx, "msg", Hex("hex_val", []byte{ 0x01, 0x02, 0x03, 0x04, 0x05, 0x06, 0x07, 0x08, @@ -221,10 +221,32 @@ var tests = []struct { log.InfoS(ctx, "msg", Hex6("hex_val", []byte{ 0x01, 0x02, 0x03, 0x04, 0x05, 0x06, 0x07, 0x08, })) + + log.InfoS(ctx, "msg", "key", Sprintf("%.12f", 3.241)) + log.InfoS(ctx, "msg", Fmt("key", "%.12f", 3.241)) + + // Create a closure that will fail the test if it is + // executed. We log it with the Debug level so that it + // is not executed. + shouldNotRun := ClosureAttr("key", func() string { + t.Fatalf("Should not compute") + return "value" + }) + log.DebugS(ctx, "msg", shouldNotRun) + + // Create a closure that should be executed since it is + // logged with the Info level. + shouldRun := ClosureAttr("key", func() string { + return "lazy compute" + }) + log.InfoS(ctx, "msg", shouldRun) }, expectedLog: `[INF]: msg hex_val=0102030405060708 [INF]: msg hex_val=0102 [INF]: msg hex_val=010203040506 +[INF]: msg key=3.241000000000 +[INF]: msg key=3.241000000000 +[INF]: msg key="lazy compute" `, }, } From 350c095851de07e78a7849500da859549d8be1c7 Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Mon, 25 Nov 2024 10:13:03 +0200 Subject: [PATCH 04/12] log: add benchmark tests for V1 and V2 loggers This commit adds two benchmark tests: 1) BenchmarkLogger tests the new V2 logger under various scenarios. 2) BenchmarkV1vsV2Loggers tests the performance of the V2 logger against that of the V1 logger. As of this commit, the biggest issue is the time it takes for the new v2 logger to perform a log action that actually gets skipped due to the current log level. This is due to a bug that builds the log string using fmt.Sprintf _before_ the logger's Enabled check is run against the current log level. This will be improved upon in the upcoming commits. The BenchmarkLogger test will also help to assess the various improvements that will be make in the upcoming commits. We ideally want BenchmarkV2vsV2Loggers to show that the performance between the same methods on the two loggers does not change much. This will be improved upon in upcoming commits. --- v2/log_test.go | 208 +++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 208 insertions(+) create mode 100644 v2/log_test.go diff --git a/v2/log_test.go b/v2/log_test.go new file mode 100644 index 0000000..aafc1dd --- /dev/null +++ b/v2/log_test.go @@ -0,0 +1,208 @@ +package btclog + +import ( + "context" + "io" + "testing" + + "github.com/btcsuite/btclog" +) + +type complexType struct { + m map[string]string + s []string +} + +var testType = complexType{ + m: map[string]string{ + "key1": "value1", + "key2": "value2", + }, + s: []string{"a", "b", "c"}, +} + +// BenchmarkLogger benchmarks the performance of the default v2 logger for each +// logging level. This helps evaluate the effect of any change to the v2 logger. +func BenchmarkLogger(b *testing.B) { + ctx := context.Background() + log := NewSLogger(NewDefaultHandler(io.Discard)) + + // Set the level to Info so that Debug logs are skipped. + log.SetLevel(LevelInfo) + + tests := []struct { + name string + logFunc func() + }{ + { + name: "Skipped Simple `f` Log", + logFunc: func() { + log.Debugf("msg") + }, + }, + { + name: "Skipped Simple `S` Log", + logFunc: func() { + log.DebugS(ctx, "msg") + }, + }, + { + name: "Simple `f` Log", + logFunc: func() { + log.Infof("msg") + }, + }, + { + name: "Simple `S` Log", + logFunc: func() { + log.InfoS(ctx, "msg") + }, + }, + { + name: "Skipped Complex `f` Log", + logFunc: func() { + log.Debugf("Debugf "+ + "request_id=%d, "+ + "complex_type=%v, "+ + "type=%T, "+ + "floating_point=%.12f, "+ + "hex_value=%x, "+ + "fmt_string=%s", + 5, testType, testType, + 3.141592653589793, []byte{0x01, 0x02}, + Sprintf("%s, %v, %T, %.12f", + "string", testType, testType, + 3.141592653589793)) + }, + }, + { + name: "Skipped Complex `S` Log", + logFunc: func() { + log.DebugS(ctx, "InfoS", + "request_id", 5, + "complex_type", testType, + Fmt("type", "%T", testType), + Fmt("floating_point", "%.12f", 3.141592653589793), + Hex("hex_value", []byte{0x01, 0x02}), + Fmt("fmt_string", "%s, %v, %T, %.12f", + "string", testType, testType, + 3.141592653589793)) + }, + }, + { + name: "Complex `f` Log", + logFunc: func() { + log.Infof("Infof "+ + "request_id=%d, "+ + "complex_type=%v, "+ + "type=%T, "+ + "floating_point=%.12f, "+ + "hex_value=%x, "+ + "fmt_string=%s", + 5, testType, testType, + 3.141592653589793, []byte{0x01, 0x02}, + Sprintf("%s, %v, %T, %.12f", + "string", testType, testType, + 3.141592653589793)) + }, + }, + { + name: "Complex `S` Log", + logFunc: func() { + log.InfoS(ctx, "InfoS", + "request_id", 5, + "complex_type", testType, + Fmt("type", "%T", testType), + Fmt("floating_point", "%.12f", 3.141592653589793), + Hex("hex_value", []byte{0x01, 0x02}), + Fmt("fmt_string", "%s, %v, %T, %.12f", + "string", testType, testType, + 3.141592653589793)) + }, + }, + } + + for _, test := range tests { + b.Run(test.name, func(b *testing.B) { + for i := 0; i < b.N; i++ { + test.logFunc() + } + }) + } +} + +// BenchmarkV1vsV2Loggers compares the performance of the btclog V1 logger to +// the btclog V2 logger in various logs that can be used with both the legacy +// Logger interface along with the new Logger interface. This, in other words, +// therefore compares the performance change when the V1 logger is swapped out +// for the V2 logger. +func BenchmarkV1vsV2Loggers(b *testing.B) { + loggers := []struct { + name string + btclog.Logger + }{ + { + name: "btclog v1", + Logger: btclog.NewBackend(io.Discard).Logger("V1"), + }, + { + name: "btclog v2", + Logger: NewSLogger(NewDefaultHandler(io.Discard)), + }, + } + + for _, logger := range loggers { + // Test a basic message log with no formatted strings. + b.Run(logger.name+" simple", func(b *testing.B) { + for i := 0; i < b.N; i++ { + logger.Infof("Basic") + } + }) + + // Test a basic message log with no formatted strings that gets + // skipped due to the current log level. + b.Run(logger.name+" skipped simple", func(b *testing.B) { + for i := 0; i < b.N; i++ { + logger.Debugf("Basic") + } + }) + + // Test a log line with a variety of different types and + // formats. + b.Run(logger.name+" complex", func(b *testing.B) { + for i := 0; i < b.N; i++ { + logger.Infof("Infof "+ + "request_id=%d, "+ + "complex_type=%v, "+ + "type=%T, "+ + "floating_point=%.12f, "+ + "hex_value=%x, "+ + "fmt_string=%s", + 5, testType, testType, + 3.141592653589793, []byte{0x01, 0x02}, + Sprintf("%s, %v, %T, %.12f", + "string", testType, testType, + 3.141592653589793)) + } + }) + + // Test a log line with a variety of different types and formats + // that then gets skipped due to the current log level. + b.Run(logger.name+" skipped complex", func(b *testing.B) { + for i := 0; i < b.N; i++ { + logger.Debugf("Infof "+ + "request_id=%d, "+ + "complex_type=%v, "+ + "type=%T, "+ + "floating_point=%.12f, "+ + "hex_value=%x, "+ + "fmt_string=%s", + 5, testType, testType, + 3.141592653589793, []byte{0x01, 0x02}, + Sprintf("%s, %v, %T, %.12f", + "string", testType, testType, + 3.141592653589793)) + } + }) + } +} From 02ac0c52cefaa7eda4c632f843c2c785ca68b06b Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Mon, 25 Nov 2024 10:28:00 +0200 Subject: [PATCH 05/12] log: one context per logger Instead of a fresh context per call to the old interface methods. --- v2/attrs.go | 4 ++-- v2/log.go | 23 +++++++++++++++++------ 2 files changed, 19 insertions(+), 8 deletions(-) diff --git a/v2/attrs.go b/v2/attrs.go index d9af6b4..8b9f34e 100644 --- a/v2/attrs.go +++ b/v2/attrs.go @@ -51,9 +51,9 @@ type attrsKey struct{} // // Usage: // -// ctx := log.WithCtx(ctx, "height", 1234) +// unusedCtx := log.WithCtx(unusedCtx, "height", 1234) // ... -// log.Info(ctx, "Height processed") // Will contain attribute: height=1234 +// log.Info(unusedCtx, "Height processed") // Will contain attribute: height=1234 func WithCtx(ctx context.Context, attrs ...any) context.Context { return context.WithValue(ctx, attrsKey{}, mergeAttrs(ctx, attrs)) } diff --git a/v2/log.go b/v2/log.go index 754c3c7..93479f8 100644 --- a/v2/log.go +++ b/v2/log.go @@ -3,9 +3,10 @@ package btclog import ( "context" "fmt" - "github.com/btcsuite/btclog" "io" "log/slog" + + "github.com/btcsuite/btclog" ) // Disabled is a Logger that will never output anything. @@ -31,13 +32,24 @@ type Handler interface { type sLogger struct { Handler logger *slog.Logger + + // unusedCtx is a context that will be passed to the non-structured + // logging calls for backwards compatibility with the old v1 Logger + // interface. Transporting a context in a struct is an anti-pattern but + // this is purely used for backwards compatibility and to prevent + // needing to create a fresh context for each call to the old interface + // methods. This is ok to do since the slog package does not use this + // context for cancellation or deadlines. It purely uses it to extract + // any slog attributes that have been added as values to the context. + unusedCtx context.Context } // NewSLogger constructs a new structured logger from the given Handler. func NewSLogger(handler Handler) Logger { return &sLogger{ - Handler: handler, - logger: slog.New(handler), + Handler: handler, + logger: slog.New(handler), + unusedCtx: context.Background(), } } @@ -206,15 +218,14 @@ func (l *sLogger) CriticalS(ctx context.Context, msg string, err error, // contains a format string and parameters for the string into the appropriate // form expected by the structured logger. func (l *sLogger) toSlogf(level slog.Level, format string, params ...any) { - l.logger.Log(context.Background(), level, - fmt.Sprintf(format, params...)) + l.logger.Log(l.unusedCtx, level, fmt.Sprintf(format, params...)) } // toSlog is a helper method that converts an unstructured log call that // contains a number of parameters into the appropriate form expected by the // structured logger. func (l *sLogger) toSlog(level slog.Level, v ...any) { - l.logger.Log(context.Background(), level, fmt.Sprint(v...)) + l.logger.Log(l.unusedCtx, level, fmt.Sprint(v...)) } // toSlogS is a helper method that can be used by all the structured log calls From a08e5b6f963e32acaa8769c6c92eaa5f4fd9885d Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Mon, 25 Nov 2024 10:29:17 +0200 Subject: [PATCH 06/12] log: check level before building strings In this commit, we start checking the log level of the logger's handler before we do any more evaluation. This does not change behaviour since the level is checked by the slog library itself later on but by then we have performed some evaluation which impacts performance. In the benchmark tests, the biggest differences should be noticeable in the "skipped" tests. --- v2/log.go | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/v2/log.go b/v2/log.go index 93479f8..ac0f5e1 100644 --- a/v2/log.go +++ b/v2/log.go @@ -218,6 +218,10 @@ func (l *sLogger) CriticalS(ctx context.Context, msg string, err error, // contains a format string and parameters for the string into the appropriate // form expected by the structured logger. func (l *sLogger) toSlogf(level slog.Level, format string, params ...any) { + if !l.Enabled(l.unusedCtx, level) { + return + } + l.logger.Log(l.unusedCtx, level, fmt.Sprintf(format, params...)) } @@ -225,6 +229,10 @@ func (l *sLogger) toSlogf(level slog.Level, format string, params ...any) { // contains a number of parameters into the appropriate form expected by the // structured logger. func (l *sLogger) toSlog(level slog.Level, v ...any) { + if !l.Enabled(l.unusedCtx, level) { + return + } + l.logger.Log(l.unusedCtx, level, fmt.Sprint(v...)) } @@ -233,6 +241,10 @@ func (l *sLogger) toSlog(level slog.Level, v ...any) { func (l *sLogger) toSlogS(ctx context.Context, level slog.Level, msg string, attrs ...any) { + if !l.Enabled(ctx, level) { + return + } + l.logger.Log(ctx, level, msg, mergeAttrs(ctx, attrs)...) } From 87220081a6155d03f6665d05aed44b32972593e0 Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Fri, 22 Nov 2024 16:06:06 +0200 Subject: [PATCH 07/12] handler: only use fmt.Sprintf in styled outputs when specified The default styled options use `fmt.Sprintf` calls. This commit removes these defaults which improves the performance of the V2 logger for the cases when styled options are not provided. --- v2/handler.go | 45 ++++++++++++++++++++++++++++++--------------- v2/handler_test.go | 45 ++++++++++++++++++++++++++++++++++++++++++++- 2 files changed, 74 insertions(+), 16 deletions(-) diff --git a/v2/handler.go b/v2/handler.go index 1b15b17..a6a67af 100644 --- a/v2/handler.go +++ b/v2/handler.go @@ -55,15 +55,6 @@ func defaultHandlerOpts() *handlerOpts { flag: defaultFlags, withTimestamp: true, callSiteSkipDepth: 6, - styledLevel: func(level btclog.Level) string { - return fmt.Sprintf("[%s]", level) - }, - styledCallSite: func(file string, line int) string { - return fmt.Sprintf("%s:%d", file, line) - }, - styledKey: func(s string) string { - return s - }, } } @@ -216,7 +207,8 @@ func (d *DefaultHandler) Handle(_ context.Context, r slog.Record) error { } // Finish off the header. - buf.writeString(": ") + buf.writeByte(':') + buf.writeByte(' ') // Write the log message itself. if r.Message != "" { @@ -309,7 +301,16 @@ func (d *DefaultHandler) appendAttr(buf *buffer, a slog.Attr) { // writeLevel writes the given slog.Level to the buffer in its string form. func (d *DefaultHandler) writeLevel(buf *buffer, level slog.Level) { - buf.writeString(d.opts.styledLevel(fromSlogLevel(level))) + lvl := fromSlogLevel(level) + if d.opts.styledLevel != nil { + buf.writeString(d.opts.styledLevel(fromSlogLevel(level))) + + return + } + + buf.writeByte('[') + buf.writeString(lvl.String()) + buf.writeByte(']') } // writeCallSite writes the given file path and line number to the buffer as a @@ -318,9 +319,17 @@ func (d *DefaultHandler) writeCallSite(buf *buffer, file string, line int) { if file == "" { return } - buf.writeString(" ") + buf.writeByte(' ') + + if d.opts.styledCallSite != nil { + buf.writeString(d.opts.styledCallSite(file, line)) + + return + } - buf.writeString(d.opts.styledCallSite(file, line)) + *buf = append(*buf, file...) + buf.writeByte(':') + itoa(buf, line, -1) } // appendString writes the given string to the buffer. It may wrap the string in @@ -336,13 +345,19 @@ func appendString(buf *buffer, str string) { // appendKey writes the given key string to the buffer along with an `=` // character. This is generally useful before calling appendValue. func (d *DefaultHandler) appendKey(buf *buffer, key string) { - buf.writeString(" ") + buf.writeByte(' ') if needsQuoting(key) { key = strconv.Quote(key) } key += "=" - buf.writeString(d.opts.styledKey(key)) + if d.opts.styledKey != nil { + buf.writeString(d.opts.styledKey(key)) + + return + } + + buf.writeString(key) } // appendValue writes the given slog.Value to the buffer. diff --git a/v2/handler_test.go b/v2/handler_test.go index a3a7467..8f90a9a 100644 --- a/v2/handler_test.go +++ b/v2/handler_test.go @@ -4,6 +4,7 @@ import ( "bytes" "context" "errors" + "fmt" "io" "testing" "time" @@ -79,7 +80,7 @@ var tests = []struct { logFunc: func(t *testing.T, log Logger) { log.Info("Test Basic Log") }, - expectedLog: `[INF] handler_test.go:29: Test Basic Log + expectedLog: `[INF] handler_test.go:30: Test Basic Log `, }, { @@ -247,6 +248,48 @@ var tests = []struct { [INF]: msg key=3.241000000000 [INF]: msg key=3.241000000000 [INF]: msg key="lazy compute" +`, + }, + { + name: "Styled Outputs", + handlerConstructor: func(w io.Writer) Handler { + return NewDefaultHandler( + w, WithNoTimestamp(), + WithCallSiteSkipDepth(7), + WithCallerFlags(Lshortfile), + WithStyledKeys(func(s string) string { + return s + }), + WithStyledCallSite( + func(f string, l int) string { + return fmt.Sprintf( + "%s:%d", f, l, + ) + }, + ), + WithStyledLevel( + func(l btclog.Level) string { + return fmt.Sprintf( + "[%s]", l, + ) + }, + ), + ) + }, + level: LevelInfo, + logFunc: func(t *testing.T, log Logger) { + ctx := context.Background() + log.InfoS(ctx, "No attributes") + log.InfoS(ctx, "Single word attribute", "key", "value") + log.InfoS(ctx, "Multi word string value", "key with spaces", "value") + log.InfoS(ctx, "Number attribute", "key", 5) + log.InfoS(ctx, "Bad key", "key") + }, + expectedLog: `[INF] handler_test.go:30: No attributes +[INF] handler_test.go:30: Single word attribute key=value +[INF] handler_test.go:30: Multi word string value "key with spaces"=value +[INF] handler_test.go:30: Number attribute key=5 +[INF] handler_test.go:30: Bad key !BADKEY=key `, }, } From 054acdb629431d3dfb8053aa59f83b2758f7d815 Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Mon, 25 Nov 2024 07:55:54 +0200 Subject: [PATCH 08/12] log: remove the toSlog* helpers To prioritise performance of the logger, we opt for code duplication instead of adding an extra code jump to the call-stack. --- v2/handler.go | 2 +- v2/handler_test.go | 4 +- v2/log.go | 139 +++++++++++++++++++++++++++++---------------- 3 files changed, 92 insertions(+), 53 deletions(-) diff --git a/v2/handler.go b/v2/handler.go index a6a67af..a8e96a7 100644 --- a/v2/handler.go +++ b/v2/handler.go @@ -54,7 +54,7 @@ func defaultHandlerOpts() *handlerOpts { return &handlerOpts{ flag: defaultFlags, withTimestamp: true, - callSiteSkipDepth: 6, + callSiteSkipDepth: 5, } } diff --git a/v2/handler_test.go b/v2/handler_test.go index 8f90a9a..2af1170 100644 --- a/v2/handler_test.go +++ b/v2/handler_test.go @@ -72,7 +72,7 @@ var tests = []struct { handlerConstructor: func(w io.Writer) Handler { return NewDefaultHandler( w, WithNoTimestamp(), - WithCallSiteSkipDepth(7), + WithCallSiteSkipDepth(6), WithCallerFlags(Lshortfile), ) }, @@ -255,7 +255,7 @@ var tests = []struct { handlerConstructor: func(w io.Writer) Handler { return NewDefaultHandler( w, WithNoTimestamp(), - WithCallSiteSkipDepth(7), + WithCallSiteSkipDepth(6), WithCallerFlags(Lshortfile), WithStyledKeys(func(s string) string { return s diff --git a/v2/log.go b/v2/log.go index ac0f5e1..63bdffd 100644 --- a/v2/log.go +++ b/v2/log.go @@ -58,7 +58,11 @@ func NewSLogger(handler Handler) Logger { // // This is part of the Logger interface implementation. func (l *sLogger) Tracef(format string, params ...any) { - l.toSlogf(levelTrace, format, params...) + if !l.Enabled(l.unusedCtx, levelTrace) { + return + } + + l.logger.Log(l.unusedCtx, levelTrace, fmt.Sprintf(format, params...)) } // Debugf creates a formatted message from the to format specifier along with @@ -66,7 +70,11 @@ func (l *sLogger) Tracef(format string, params ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Debugf(format string, params ...any) { - l.toSlogf(levelDebug, format, params...) + if !l.Enabled(l.unusedCtx, levelDebug) { + return + } + + l.logger.Log(l.unusedCtx, levelDebug, fmt.Sprintf(format, params...)) } // Infof creates a formatted message from the to format specifier along with @@ -74,7 +82,11 @@ func (l *sLogger) Debugf(format string, params ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Infof(format string, params ...any) { - l.toSlogf(levelInfo, format, params...) + if !l.Enabled(l.unusedCtx, levelInfo) { + return + } + + l.logger.Log(l.unusedCtx, levelInfo, fmt.Sprintf(format, params...)) } // Warnf creates a formatted message from the to format specifier along with @@ -82,7 +94,11 @@ func (l *sLogger) Infof(format string, params ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Warnf(format string, params ...any) { - l.toSlogf(levelWarn, format, params...) + if !l.Enabled(l.unusedCtx, levelWarn) { + return + } + + l.logger.Log(l.unusedCtx, levelWarn, fmt.Sprintf(format, params...)) } // Errorf creates a formatted message from the to format specifier along with @@ -90,7 +106,11 @@ func (l *sLogger) Warnf(format string, params ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Errorf(format string, params ...any) { - l.toSlogf(levelError, format, params...) + if !l.Enabled(l.unusedCtx, levelError) { + return + } + + l.logger.Log(l.unusedCtx, levelError, fmt.Sprintf(format, params...)) } // Criticalf creates a formatted message from the to format specifier along @@ -98,7 +118,11 @@ func (l *sLogger) Errorf(format string, params ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Criticalf(format string, params ...any) { - l.toSlogf(levelCritical, format, params...) + if !l.Enabled(l.unusedCtx, levelCritical) { + return + } + + l.logger.Log(l.unusedCtx, levelCritical, fmt.Sprintf(format, params...)) } // Trace formats a message using the default formats for its operands, prepends @@ -106,7 +130,11 @@ func (l *sLogger) Criticalf(format string, params ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Trace(v ...any) { - l.toSlog(levelTrace, v...) + if !l.Enabled(l.unusedCtx, levelTrace) { + return + } + + l.logger.Log(l.unusedCtx, levelTrace, fmt.Sprint(v...)) } // Debug formats a message using the default formats for its operands, prepends @@ -114,7 +142,11 @@ func (l *sLogger) Trace(v ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Debug(v ...any) { - l.toSlog(levelDebug, v...) + if !l.Enabled(l.unusedCtx, levelDebug) { + return + } + + l.logger.Log(l.unusedCtx, levelDebug, fmt.Sprint(v...)) } // Info formats a message using the default formats for its operands, prepends @@ -122,7 +154,11 @@ func (l *sLogger) Debug(v ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Info(v ...any) { - l.toSlog(levelInfo, v...) + if !l.Enabled(l.unusedCtx, levelInfo) { + return + } + + l.logger.Log(l.unusedCtx, levelInfo, fmt.Sprint(v...)) } // Warn formats a message using the default formats for its operands, prepends @@ -130,7 +166,11 @@ func (l *sLogger) Info(v ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Warn(v ...any) { - l.toSlog(levelWarn, v...) + if !l.Enabled(l.unusedCtx, levelWarn) { + return + } + + l.logger.Log(l.unusedCtx, levelWarn, fmt.Sprint(v...)) } // Error formats a message using the default formats for its operands, prepends @@ -138,7 +178,11 @@ func (l *sLogger) Warn(v ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Error(v ...any) { - l.toSlog(levelError, v...) + if !l.Enabled(l.unusedCtx, levelError) { + return + } + + l.logger.Log(l.unusedCtx, levelError, fmt.Sprint(v...)) } // Critical formats a message using the default formats for its operands, @@ -146,7 +190,11 @@ func (l *sLogger) Error(v ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Critical(v ...any) { - l.toSlog(levelCritical, v...) + if !l.Enabled(l.unusedCtx, levelCritical) { + return + } + + l.logger.Log(l.unusedCtx, levelCritical, fmt.Sprint(v...)) } // TraceS writes a structured log with the given message and key-value pair @@ -154,7 +202,11 @@ func (l *sLogger) Critical(v ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) TraceS(ctx context.Context, msg string, attrs ...any) { - l.toSlogS(ctx, levelTrace, msg, attrs...) + if !l.Enabled(ctx, levelTrace) { + return + } + + l.logger.Log(ctx, levelTrace, msg, mergeAttrs(ctx, attrs)...) } // DebugS writes a structured log with the given message and key-value pair @@ -162,7 +214,11 @@ func (l *sLogger) TraceS(ctx context.Context, msg string, attrs ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) DebugS(ctx context.Context, msg string, attrs ...any) { - l.toSlogS(ctx, levelDebug, msg, attrs...) + if !l.Enabled(ctx, levelDebug) { + return + } + + l.logger.Log(ctx, levelDebug, msg, mergeAttrs(ctx, attrs)...) } // InfoS writes a structured log with the given message and key-value pair @@ -170,7 +226,11 @@ func (l *sLogger) DebugS(ctx context.Context, msg string, attrs ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) InfoS(ctx context.Context, msg string, attrs ...any) { - l.toSlogS(ctx, levelInfo, msg, attrs...) + if !l.Enabled(ctx, levelInfo) { + return + } + + l.logger.Log(ctx, levelInfo, msg, mergeAttrs(ctx, attrs)...) } // WarnS writes a structured log with the given message and key-value pair @@ -180,11 +240,15 @@ func (l *sLogger) InfoS(ctx context.Context, msg string, attrs ...any) { func (l *sLogger) WarnS(ctx context.Context, msg string, err error, attrs ...any) { + if !l.Enabled(ctx, levelWarn) { + return + } + if err != nil { attrs = append([]any{slog.String("err", err.Error())}, attrs...) } - l.toSlogS(ctx, levelWarn, msg, attrs...) + l.logger.Log(ctx, levelWarn, msg, mergeAttrs(ctx, attrs)...) } // ErrorS writes a structured log with the given message and key-value pair @@ -194,11 +258,15 @@ func (l *sLogger) WarnS(ctx context.Context, msg string, err error, func (l *sLogger) ErrorS(ctx context.Context, msg string, err error, attrs ...any) { + if !l.Enabled(ctx, levelError) { + return + } + if err != nil { attrs = append([]any{slog.String("err", err.Error())}, attrs...) } - l.toSlogS(ctx, levelError, msg, attrs...) + l.logger.Log(ctx, levelError, msg, mergeAttrs(ctx, attrs)...) } // CriticalS writes a structured log with the given message and key-value pair @@ -207,45 +275,16 @@ func (l *sLogger) ErrorS(ctx context.Context, msg string, err error, // This is part of the Logger interface implementation. func (l *sLogger) CriticalS(ctx context.Context, msg string, err error, attrs ...any) { - if err != nil { - attrs = append([]any{slog.String("err", err.Error())}, attrs...) - } - - l.toSlogS(ctx, levelCritical, msg, attrs...) -} -// toSlogf is a helper method that converts an unstructured log call that -// contains a format string and parameters for the string into the appropriate -// form expected by the structured logger. -func (l *sLogger) toSlogf(level slog.Level, format string, params ...any) { - if !l.Enabled(l.unusedCtx, level) { + if !l.Enabled(ctx, levelCritical) { return } - l.logger.Log(l.unusedCtx, level, fmt.Sprintf(format, params...)) -} - -// toSlog is a helper method that converts an unstructured log call that -// contains a number of parameters into the appropriate form expected by the -// structured logger. -func (l *sLogger) toSlog(level slog.Level, v ...any) { - if !l.Enabled(l.unusedCtx, level) { - return - } - - l.logger.Log(l.unusedCtx, level, fmt.Sprint(v...)) -} - -// toSlogS is a helper method that can be used by all the structured log calls -// to access the underlying logger. -func (l *sLogger) toSlogS(ctx context.Context, level slog.Level, msg string, - attrs ...any) { - - if !l.Enabled(ctx, level) { - return + if err != nil { + attrs = append([]any{slog.String("err", err.Error())}, attrs...) } - l.logger.Log(ctx, level, msg, mergeAttrs(ctx, attrs)...) + l.logger.Log(ctx, levelCritical, msg, mergeAttrs(ctx, attrs)...) } var _ Logger = (*sLogger)(nil) From 72ac01eb0166fa23aa09c589d2df6575ebaf8869 Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Mon, 25 Nov 2024 08:15:07 +0200 Subject: [PATCH 09/12] log: Let the logger directly carry the level In this commit, instead of depending on the Handler for Level handling, we add a level object to the logger itself. This makes checking the log level before computing any expensive checks much faster. The handler still needs to carry its own level member so that it can properly implement the `Enabled` method of the Handler interface. This means that for the cases where a log line is skipped due to log level not being met, the performance will be faster. However, in the cases where the log line will be printed, execution will be slightly slower due to the fact that the level will in essence be checked twice. --- v2/handler_test.go | 17 ++++++------ v2/log.go | 65 ++++++++++++++++++++++++++++++---------------- 2 files changed, 52 insertions(+), 30 deletions(-) diff --git a/v2/handler_test.go b/v2/handler_test.go index 2af1170..636ed62 100644 --- a/v2/handler_test.go +++ b/v2/handler_test.go @@ -20,14 +20,15 @@ func TestDefaultHandler(t *testing.T) { t.Run(test.name, func(t *testing.T) { var buf bytes.Buffer handler := test.handlerConstructor(&buf) - handler.SetLevel(test.level) + logger := NewSLogger(handler) + logger.SetLevel(test.level) if handler.Level() != test.level { t.Fatalf("Incorrect level. Expected %s, "+ "got %s", test.level, handler.Level()) } - test.logFunc(t, NewSLogger(handler)) + test.logFunc(t, logger) if buf.String() != test.expectedLog { t.Fatalf("Log result mismatch. Expected "+ @@ -80,7 +81,7 @@ var tests = []struct { logFunc: func(t *testing.T, log Logger) { log.Info("Test Basic Log") }, - expectedLog: `[INF] handler_test.go:30: Test Basic Log + expectedLog: `[INF] handler_test.go:31: Test Basic Log `, }, { @@ -285,11 +286,11 @@ var tests = []struct { log.InfoS(ctx, "Number attribute", "key", 5) log.InfoS(ctx, "Bad key", "key") }, - expectedLog: `[INF] handler_test.go:30: No attributes -[INF] handler_test.go:30: Single word attribute key=value -[INF] handler_test.go:30: Multi word string value "key with spaces"=value -[INF] handler_test.go:30: Number attribute key=5 -[INF] handler_test.go:30: Bad key !BADKEY=key + expectedLog: `[INF] handler_test.go:31: No attributes +[INF] handler_test.go:31: Single word attribute key=value +[INF] handler_test.go:31: Multi word string value "key with spaces"=value +[INF] handler_test.go:31: Number attribute key=5 +[INF] handler_test.go:31: Bad key !BADKEY=key `, }, } diff --git a/v2/log.go b/v2/log.go index 63bdffd..f7af277 100644 --- a/v2/log.go +++ b/v2/log.go @@ -5,6 +5,7 @@ import ( "fmt" "io" "log/slog" + "sync/atomic" "github.com/btcsuite/btclog" ) @@ -30,8 +31,10 @@ type Handler interface { // sLogger is an implementation of Logger backed by a structured sLogger. type sLogger struct { - Handler - logger *slog.Logger + level atomic.Int64 + + handler Handler + logger *slog.Logger // unusedCtx is a context that will be passed to the non-structured // logging calls for backwards compatibility with the old v1 Logger @@ -46,11 +49,14 @@ type sLogger struct { // NewSLogger constructs a new structured logger from the given Handler. func NewSLogger(handler Handler) Logger { - return &sLogger{ - Handler: handler, + l := &sLogger{ + handler: handler, logger: slog.New(handler), unusedCtx: context.Background(), } + l.level.Store(int64(toSlogLevel(handler.Level()))) + + return l } // Tracef creates a formatted message from the to format specifier along with @@ -58,7 +64,7 @@ func NewSLogger(handler Handler) Logger { // // This is part of the Logger interface implementation. func (l *sLogger) Tracef(format string, params ...any) { - if !l.Enabled(l.unusedCtx, levelTrace) { + if l.level.Load() > int64(levelTrace) { return } @@ -70,7 +76,7 @@ func (l *sLogger) Tracef(format string, params ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Debugf(format string, params ...any) { - if !l.Enabled(l.unusedCtx, levelDebug) { + if l.level.Load() > int64(levelDebug) { return } @@ -82,7 +88,7 @@ func (l *sLogger) Debugf(format string, params ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Infof(format string, params ...any) { - if !l.Enabled(l.unusedCtx, levelInfo) { + if l.level.Load() > int64(levelInfo) { return } @@ -94,7 +100,7 @@ func (l *sLogger) Infof(format string, params ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Warnf(format string, params ...any) { - if !l.Enabled(l.unusedCtx, levelWarn) { + if l.level.Load() > int64(levelWarn) { return } @@ -106,7 +112,7 @@ func (l *sLogger) Warnf(format string, params ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Errorf(format string, params ...any) { - if !l.Enabled(l.unusedCtx, levelError) { + if l.level.Load() > int64(levelError) { return } @@ -118,7 +124,7 @@ func (l *sLogger) Errorf(format string, params ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Criticalf(format string, params ...any) { - if !l.Enabled(l.unusedCtx, levelCritical) { + if l.level.Load() > int64(levelCritical) { return } @@ -130,7 +136,7 @@ func (l *sLogger) Criticalf(format string, params ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Trace(v ...any) { - if !l.Enabled(l.unusedCtx, levelTrace) { + if l.level.Load() > int64(levelTrace) { return } @@ -142,7 +148,7 @@ func (l *sLogger) Trace(v ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Debug(v ...any) { - if !l.Enabled(l.unusedCtx, levelDebug) { + if l.level.Load() > int64(levelDebug) { return } @@ -154,7 +160,7 @@ func (l *sLogger) Debug(v ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Info(v ...any) { - if !l.Enabled(l.unusedCtx, levelInfo) { + if l.level.Load() > int64(levelInfo) { return } @@ -166,7 +172,7 @@ func (l *sLogger) Info(v ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Warn(v ...any) { - if !l.Enabled(l.unusedCtx, levelWarn) { + if l.level.Load() > int64(levelWarn) { return } @@ -178,7 +184,7 @@ func (l *sLogger) Warn(v ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Error(v ...any) { - if !l.Enabled(l.unusedCtx, levelError) { + if l.level.Load() > int64(levelError) { return } @@ -190,7 +196,7 @@ func (l *sLogger) Error(v ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) Critical(v ...any) { - if !l.Enabled(l.unusedCtx, levelCritical) { + if l.level.Load() > int64(levelCritical) { return } @@ -202,7 +208,7 @@ func (l *sLogger) Critical(v ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) TraceS(ctx context.Context, msg string, attrs ...any) { - if !l.Enabled(ctx, levelTrace) { + if l.level.Load() > int64(levelTrace) { return } @@ -214,7 +220,7 @@ func (l *sLogger) TraceS(ctx context.Context, msg string, attrs ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) DebugS(ctx context.Context, msg string, attrs ...any) { - if !l.Enabled(ctx, levelDebug) { + if l.level.Load() > int64(levelDebug) { return } @@ -226,7 +232,7 @@ func (l *sLogger) DebugS(ctx context.Context, msg string, attrs ...any) { // // This is part of the Logger interface implementation. func (l *sLogger) InfoS(ctx context.Context, msg string, attrs ...any) { - if !l.Enabled(ctx, levelInfo) { + if l.level.Load() > int64(levelInfo) { return } @@ -240,7 +246,7 @@ func (l *sLogger) InfoS(ctx context.Context, msg string, attrs ...any) { func (l *sLogger) WarnS(ctx context.Context, msg string, err error, attrs ...any) { - if !l.Enabled(ctx, levelWarn) { + if l.level.Load() > int64(levelWarn) { return } @@ -258,7 +264,7 @@ func (l *sLogger) WarnS(ctx context.Context, msg string, err error, func (l *sLogger) ErrorS(ctx context.Context, msg string, err error, attrs ...any) { - if !l.Enabled(ctx, levelError) { + if l.level.Load() > int64(levelError) { return } @@ -276,7 +282,7 @@ func (l *sLogger) ErrorS(ctx context.Context, msg string, err error, func (l *sLogger) CriticalS(ctx context.Context, msg string, err error, attrs ...any) { - if !l.Enabled(ctx, levelCritical) { + if l.level.Load() > int64(levelCritical) { return } @@ -287,6 +293,21 @@ func (l *sLogger) CriticalS(ctx context.Context, msg string, err error, l.logger.Log(ctx, levelCritical, msg, mergeAttrs(ctx, attrs)...) } +// Level returns the current logging level of the Handler. +// +// This is part of the Logger interface implementation. +func (l *sLogger) Level() btclog.Level { + return fromSlogLevel(slog.Level(l.level.Load())) +} + +// SetLevel changes the logging level of the Handler to the passed level. +// +// This is part of the Logger interface implementation. +func (l *sLogger) SetLevel(level btclog.Level) { + l.level.Store(int64(toSlogLevel(level))) + l.handler.SetLevel(level) +} + var _ Logger = (*sLogger)(nil) func init() { From e669d22b89707c1b41c81f72fd597c7feb0826ba Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Mon, 25 Nov 2024 11:44:34 +0200 Subject: [PATCH 10/12] log: add SubSystem method to Logger interface So that a sub-system logger can be derived directly from a logger rather than needing to first create a new handler. --- v2/handler_test.go | 135 +++++++++++++++++++-------------------------- v2/interface.go | 4 ++ v2/log.go | 7 +++ 3 files changed, 69 insertions(+), 77 deletions(-) diff --git a/v2/handler_test.go b/v2/handler_test.go index 636ed62..d239450 100644 --- a/v2/handler_test.go +++ b/v2/handler_test.go @@ -5,7 +5,6 @@ import ( "context" "errors" "fmt" - "io" "testing" "time" @@ -19,7 +18,7 @@ func TestDefaultHandler(t *testing.T) { for _, test := range tests { t.Run(test.name, func(t *testing.T) { var buf bytes.Buffer - handler := test.handlerConstructor(&buf) + handler := NewDefaultHandler(&buf, test.handlerOpts...) logger := NewSLogger(handler) logger.SetLevel(test.level) @@ -45,20 +44,16 @@ var timeSource = func() time.Time { } var tests = []struct { - name string - handlerConstructor func(w io.Writer) Handler - level btclog.Level - logFunc func(t *testing.T, log Logger) - expectedLog string + name string + handlerOpts []HandlerOption + level btclog.Level + logFunc func(t *testing.T, log Logger) + expectedLog string }{ { - name: "Basic calls and levels", - handlerConstructor: func(w io.Writer) Handler { - return NewDefaultHandler( - w, WithTimeSource(timeSource), - ) - }, - level: LevelDebug, + name: "Basic calls and levels", + handlerOpts: []HandlerOption{WithTimeSource(timeSource)}, + level: LevelDebug, logFunc: func(t *testing.T, log Logger) { log.Info("Test Basic Log") log.Debugf("Test basic log with %s", "format") @@ -70,39 +65,33 @@ var tests = []struct { }, { name: "Call site", - handlerConstructor: func(w io.Writer) Handler { - return NewDefaultHandler( - w, WithNoTimestamp(), - WithCallSiteSkipDepth(6), - WithCallerFlags(Lshortfile), - ) + handlerOpts: []HandlerOption{ + WithNoTimestamp(), + WithCallSiteSkipDepth(6), + WithCallerFlags(Lshortfile), }, level: LevelInfo, logFunc: func(t *testing.T, log Logger) { log.Info("Test Basic Log") }, - expectedLog: `[INF] handler_test.go:31: Test Basic Log + expectedLog: `[INF] handler_test.go:30: Test Basic Log `, }, { - name: "Sub-system tag", - handlerConstructor: func(w io.Writer) Handler { - h := NewDefaultHandler(w, WithNoTimestamp()) - return h.SubSystem("SUBS") - }, - level: LevelInfo, + name: "Sub-system tag", + handlerOpts: []HandlerOption{WithNoTimestamp()}, + level: LevelTrace, logFunc: func(t *testing.T, log Logger) { - log.Info("Test Basic Log") + subLog := log.SubSystem("SUBS") + subLog.Trace("Test Basic Log") }, - expectedLog: `[INF] SUBS: Test Basic Log + expectedLog: `[TRC] SUBS: Test Basic Log `, }, { - name: "Test all levels", - handlerConstructor: func(w io.Writer) Handler { - return NewDefaultHandler(w, WithNoTimestamp()) - }, - level: LevelTrace, + name: "Test all levels", + handlerOpts: []HandlerOption{WithNoTimestamp()}, + level: LevelTrace, logFunc: func(t *testing.T, log Logger) { log.Trace("Trace") log.Debug("Debug") @@ -120,11 +109,9 @@ var tests = []struct { `, }, { - name: "Structured Logs", - handlerConstructor: func(w io.Writer) Handler { - return NewDefaultHandler(w, WithNoTimestamp()) - }, - level: LevelInfo, + name: "Structured Logs", + handlerOpts: []HandlerOption{WithNoTimestamp()}, + level: LevelInfo, logFunc: func(t *testing.T, log Logger) { ctx := context.Background() log.InfoS(ctx, "No attributes") @@ -159,11 +146,9 @@ var tests = []struct { `, }, { - name: "Error logs", - handlerConstructor: func(w io.Writer) Handler { - return NewDefaultHandler(w, WithNoTimestamp()) - }, - level: LevelInfo, + name: "Error logs", + handlerOpts: []HandlerOption{WithNoTimestamp()}, + level: LevelInfo, logFunc: func(t *testing.T, log Logger) { log.Error("Error string") log.Errorf("Error formatted string") @@ -207,11 +192,9 @@ var tests = []struct { `, }, { - name: "Slog Helpers", - handlerConstructor: func(w io.Writer) Handler { - return NewDefaultHandler(w, WithNoTimestamp()) - }, - level: LevelInfo, + name: "Slog Helpers", + handlerOpts: []HandlerOption{WithNoTimestamp()}, + level: LevelInfo, logFunc: func(t *testing.T, log Logger) { ctx := context.Background() log.InfoS(ctx, "msg", Hex("hex_val", []byte{ @@ -253,29 +236,27 @@ var tests = []struct { }, { name: "Styled Outputs", - handlerConstructor: func(w io.Writer) Handler { - return NewDefaultHandler( - w, WithNoTimestamp(), - WithCallSiteSkipDepth(6), - WithCallerFlags(Lshortfile), - WithStyledKeys(func(s string) string { - return s - }), - WithStyledCallSite( - func(f string, l int) string { - return fmt.Sprintf( - "%s:%d", f, l, - ) - }, - ), - WithStyledLevel( - func(l btclog.Level) string { - return fmt.Sprintf( - "[%s]", l, - ) - }, - ), - ) + handlerOpts: []HandlerOption{ + WithNoTimestamp(), + WithCallSiteSkipDepth(6), + WithCallerFlags(Lshortfile), + WithStyledKeys(func(s string) string { + return s + }), + WithStyledCallSite( + func(f string, l int) string { + return fmt.Sprintf( + "%s:%d", f, l, + ) + }, + ), + WithStyledLevel( + func(l btclog.Level) string { + return fmt.Sprintf( + "[%s]", l, + ) + }, + ), }, level: LevelInfo, logFunc: func(t *testing.T, log Logger) { @@ -286,11 +267,11 @@ var tests = []struct { log.InfoS(ctx, "Number attribute", "key", 5) log.InfoS(ctx, "Bad key", "key") }, - expectedLog: `[INF] handler_test.go:31: No attributes -[INF] handler_test.go:31: Single word attribute key=value -[INF] handler_test.go:31: Multi word string value "key with spaces"=value -[INF] handler_test.go:31: Number attribute key=5 -[INF] handler_test.go:31: Bad key !BADKEY=key + expectedLog: `[INF] handler_test.go:30: No attributes +[INF] handler_test.go:30: Single word attribute key=value +[INF] handler_test.go:30: Multi word string value "key with spaces"=value +[INF] handler_test.go:30: Number attribute key=5 +[INF] handler_test.go:30: Bad key !BADKEY=key `, }, } diff --git a/v2/interface.go b/v2/interface.go index 3f82983..b4088f2 100644 --- a/v2/interface.go +++ b/v2/interface.go @@ -92,6 +92,10 @@ type Logger interface { // SetLevel changes the logging level to the passed level. SetLevel(level btclog.Level) + + // SubSystem returns a copy of the logger but with the new subsystem + // tag. + SubSystem(tag string) Logger } // Ensure that the Logger implements the btclog.Logger interface so that an diff --git a/v2/log.go b/v2/log.go index f7af277..ec85038 100644 --- a/v2/log.go +++ b/v2/log.go @@ -308,6 +308,13 @@ func (l *sLogger) SetLevel(level btclog.Level) { l.handler.SetLevel(level) } +// SubSystem returns a copy of the logger but with the new subsystem tag. +// +// This is part of the Logger interface implementation. +func (l *sLogger) SubSystem(tag string) Logger { + return NewSLogger(l.handler.SubSystem(tag)) +} + var _ Logger = (*sLogger)(nil) func init() { From 875edf9b3eea96420b4ca4da13adcdc78f054a6a Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Mon, 25 Nov 2024 11:53:40 +0200 Subject: [PATCH 11/12] log: add WithPrefix method Which can be used to derive a new prefixed logger which will prefix a provided string to any message printed by the logger. --- v2/handler.go | 30 +++++++++++++++++++++++++----- v2/handler_test.go | 22 +++++++++++++++++++++- v2/interface.go | 6 ++++++ v2/log.go | 14 ++++++++++++++ 4 files changed, 66 insertions(+), 6 deletions(-) diff --git a/v2/handler.go b/v2/handler.go index a8e96a7..703a282 100644 --- a/v2/handler.go +++ b/v2/handler.go @@ -118,6 +118,7 @@ type DefaultHandler struct { level int64 tag string + prefix string fields []slog.Attr callstackOffset bool @@ -210,6 +211,15 @@ func (d *DefaultHandler) Handle(_ context.Context, r slog.Record) error { buf.writeByte(':') buf.writeByte(' ') + // Maybe write a prefix if one has been specified. + if d.prefix != "" { + buf.writeString(d.prefix) + + if r.Message != "" { + buf.writeByte(' ') + } + } + // Write the log message itself. if r.Message != "" { buf.writeString(r.Message) @@ -238,7 +248,7 @@ func (d *DefaultHandler) Handle(_ context.Context, r slog.Record) error { // // NOTE: this is part of the slog.Handler interface. func (d *DefaultHandler) WithAttrs(attrs []slog.Attr) slog.Handler { - return d.with(d.tag, true, attrs...) + return d.with(d.tag, d.prefix, true, attrs...) } // WithGroup returns a new Handler with the given group appended to @@ -250,22 +260,31 @@ func (d *DefaultHandler) WithGroup(name string) slog.Handler { if d.tag != "" { name = d.tag + "." + name } - return d.with(name, true) + return d.with(name, d.prefix, true) } // SubSystem returns a copy of the given handler but with the new tag. All // attributes added with WithAttrs will be kept but all groups added with // WithGroup are lost. // -// NOTE: this is part of the Handler interface. +// note: this is part of the handler interface. func (d *DefaultHandler) SubSystem(tag string) Handler { - return d.with(tag, false) + return d.with(tag, d.prefix, false) +} + +// WithPrefix returns a copy of the Handler but with the given string prefixed +// to each log message. Note that the subsystem of the original logger is kept +// but any existing prefix is overridden. +// +// note: this is part of the handler interface. +func (d *DefaultHandler) WithPrefix(prefix string) Handler { + return d.with(d.tag, prefix, false) } // with returns a new logger with the given attributes added. // withCallstackOffset should be false if the caller returns a concrete // DefaultHandler and true if the caller returns the Handler interface. -func (d *DefaultHandler) with(tag string, withCallstackOffset bool, +func (d *DefaultHandler) with(tag, prefix string, withCallstackOffset bool, attrs ...slog.Attr) *DefaultHandler { d.mu.Lock() @@ -280,6 +299,7 @@ func (d *DefaultHandler) with(tag string, withCallstackOffset bool, sl.fields = append(sl.fields, attrs...) sl.callstackOffset = withCallstackOffset sl.tag = tag + sl.prefix = prefix return &sl } diff --git a/v2/handler_test.go b/v2/handler_test.go index d239450..51553d9 100644 --- a/v2/handler_test.go +++ b/v2/handler_test.go @@ -40,7 +40,6 @@ func TestDefaultHandler(t *testing.T) { var timeSource = func() time.Time { return time.Date(2009, time.January, 3, 12, 0, 0, 0, time.UTC) - } var tests = []struct { @@ -86,6 +85,27 @@ var tests = []struct { subLog.Trace("Test Basic Log") }, expectedLog: `[TRC] SUBS: Test Basic Log +`, + }, + { + name: "Prefixed logging", + handlerOpts: []HandlerOption{WithNoTimestamp()}, + level: LevelTrace, + logFunc: func(t *testing.T, log Logger) { + // We use trace level to ensure that logger level is + // carried over to the new prefixed logger. + log.Tracef("Test Basic Log") + + subLog := log.SubSystem("SUBS") + subLog.Tracef("Test Basic Log") + + pLog := subLog.WithPrefix("(Client)") + pLog.Tracef("Test Basic Log") + + }, + expectedLog: `[TRC]: Test Basic Log +[TRC] SUBS: Test Basic Log +[TRC] SUBS: (Client) Test Basic Log `, }, { diff --git a/v2/interface.go b/v2/interface.go index b4088f2..34d4903 100644 --- a/v2/interface.go +++ b/v2/interface.go @@ -2,6 +2,7 @@ package btclog import ( "context" + "github.com/btcsuite/btclog" ) @@ -96,6 +97,11 @@ type Logger interface { // SubSystem returns a copy of the logger but with the new subsystem // tag. SubSystem(tag string) Logger + + // WithPrefix returns a copy of the logger but with the given string + // prefixed to each log message. Note that the subsystem of the original + // logger is kept but any existing prefix is overridden. + WithPrefix(prefix string) Logger } // Ensure that the Logger implements the btclog.Logger interface so that an diff --git a/v2/log.go b/v2/log.go index ec85038..9145ab5 100644 --- a/v2/log.go +++ b/v2/log.go @@ -27,6 +27,11 @@ type Handler interface { // SubSystem returns a copy of the given handler but with the new tag. SubSystem(tag string) Handler + + // WithPrefix returns a copy of the Handler but with the given string + // prefixed to each log message. Note that the subsystem of the original + // logger is kept but any existing prefix is overridden. + WithPrefix(prefix string) Handler } // sLogger is an implementation of Logger backed by a structured sLogger. @@ -315,6 +320,15 @@ func (l *sLogger) SubSystem(tag string) Logger { return NewSLogger(l.handler.SubSystem(tag)) } +// WithPrefix returns a copy of the logger but with the given string prefixed to +// each log message. Note that the subsystem of the original logger is kept but +// any existing prefix is overridden. +// +// This is part of the Logger interface implementation. +func (l *sLogger) WithPrefix(prefix string) Logger { + return NewSLogger(l.handler.WithPrefix(prefix)) +} + var _ Logger = (*sLogger)(nil) func init() { From e0b4906c5b6219417514298fa560ee7a2027ff5c Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Mon, 25 Nov 2024 12:11:06 +0200 Subject: [PATCH 12/12] handler: export default skip depth --- v2/handler.go | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/v2/handler.go b/v2/handler.go index 703a282..9107a1c 100644 --- a/v2/handler.go +++ b/v2/handler.go @@ -13,6 +13,11 @@ import ( "github.com/btcsuite/btclog" ) +// DefaultSkipDepth is the default number of stack frames to ascend when +// determining the call site of a log. Users of this package may want to alter +// this depth depending on if they wrap the logger at all. +const DefaultSkipDepth = 5 + // HandlerOption is the signature of a functional option that can be used to // modify the behaviour of the DefaultHandler. type HandlerOption func(*handlerOpts) @@ -54,7 +59,7 @@ func defaultHandlerOpts() *handlerOpts { return &handlerOpts{ flag: defaultFlags, withTimestamp: true, - callSiteSkipDepth: 5, + callSiteSkipDepth: DefaultSkipDepth, } }