diff --git a/v2/attrs.go b/v2/attrs.go index 4aee922..8b9f34e 100644 --- a/v2/attrs.go +++ b/v2/attrs.go @@ -6,11 +6,42 @@ 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, 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...)) +} - return slog.String(key, h) +// 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{} @@ -20,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/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.go b/v2/handler.go index 1b15b17..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,16 +59,7 @@ func defaultHandlerOpts() *handlerOpts { return &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 - }, + callSiteSkipDepth: DefaultSkipDepth, } } @@ -127,6 +123,7 @@ type DefaultHandler struct { level int64 tag string + prefix string fields []slog.Attr callstackOffset bool @@ -216,7 +213,17 @@ func (d *DefaultHandler) Handle(_ context.Context, r slog.Record) error { } // Finish off the header. - buf.writeString(": ") + 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 != "" { @@ -246,7 +253,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 @@ -258,22 +265,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() @@ -288,6 +304,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 } @@ -309,7 +326,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 +344,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 +370,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 dfdceb0..51553d9 100644 --- a/v2/handler_test.go +++ b/v2/handler_test.go @@ -4,125 +4,158 @@ import ( "bytes" "context" "errors" - "github.com/btcsuite/btclog" - "io" + "fmt" "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 := NewDefaultHandler(&buf, test.handlerOpts...) + 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, logger) + + 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 + handlerOpts []HandlerOption + level btclog.Level + logFunc func(t *testing.T, log Logger) + expectedLog string +}{ + { + 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") + 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", + handlerOpts: []HandlerOption{ + WithNoTimestamp(), + WithCallSiteSkipDepth(6), + WithCallerFlags(Lshortfile), + }, + level: LevelInfo, + logFunc: func(t *testing.T, 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:30: Test Basic Log `, + }, + { + name: "Sub-system tag", + handlerOpts: []HandlerOption{WithNoTimestamp()}, + level: LevelTrace, + logFunc: func(t *testing.T, log Logger) { + subLog := log.SubSystem("SUBS") + subLog.Trace("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: `[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") + }, - { - 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 + expectedLog: `[TRC]: Test Basic Log +[TRC] SUBS: Test Basic Log +[TRC] SUBS: (Client) Test Basic Log +`, + }, + { + name: "Test all levels", + handlerOpts: []HandlerOption{WithNoTimestamp()}, + level: LevelTrace, + logFunc: func(t *testing.T, 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", + handlerOpts: []HandlerOption{WithNoTimestamp()}, + 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") + + 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 +164,37 @@ 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", + handlerOpts: []HandlerOption{WithNoTimestamp()}, + level: LevelInfo, + logFunc: func(t *testing.T, 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") }, - { - 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 + 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 +210,88 @@ 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 `, - }, - } + }, + { + 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{ + 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, + })) - for _, test := range tests { - t.Run(test.name, func(t *testing.T) { - var buf bytes.Buffer - handler := test.handlerConstructor(&buf) - handler.SetLevel(test.level) + log.InfoS(ctx, "msg", "key", Sprintf("%.12f", 3.241)) + log.InfoS(ctx, "msg", Fmt("key", "%.12f", 3.241)) - if handler.Level() != test.level { - t.Fatalf("Incorrect level. Expected %s, "+ - "got %s", test.level, handler.Level()) - } + // 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) - 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()) - } - }) - } + // 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" +`, + }, + { + name: "Styled Outputs", + 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) { + 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 +`, + }, } diff --git a/v2/interface.go b/v2/interface.go index 3f82983..34d4903 100644 --- a/v2/interface.go +++ b/v2/interface.go @@ -2,6 +2,7 @@ package btclog import ( "context" + "github.com/btcsuite/btclog" ) @@ -92,6 +93,15 @@ 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 + + // 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 754c3c7..9145ab5 100644 --- a/v2/log.go +++ b/v2/log.go @@ -3,9 +3,11 @@ package btclog import ( "context" "fmt" - "github.com/btcsuite/btclog" "io" "log/slog" + "sync/atomic" + + "github.com/btcsuite/btclog" ) // Disabled is a Logger that will never output anything. @@ -25,20 +27,41 @@ 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. 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 + // 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), + 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 @@ -46,7 +69,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.level.Load() > int64(levelTrace) { + return + } + + l.logger.Log(l.unusedCtx, levelTrace, fmt.Sprintf(format, params...)) } // Debugf creates a formatted message from the to format specifier along with @@ -54,7 +81,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.level.Load() > int64(levelDebug) { + return + } + + l.logger.Log(l.unusedCtx, levelDebug, fmt.Sprintf(format, params...)) } // Infof creates a formatted message from the to format specifier along with @@ -62,7 +93,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.level.Load() > int64(levelInfo) { + return + } + + l.logger.Log(l.unusedCtx, levelInfo, fmt.Sprintf(format, params...)) } // Warnf creates a formatted message from the to format specifier along with @@ -70,7 +105,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.level.Load() > int64(levelWarn) { + return + } + + l.logger.Log(l.unusedCtx, levelWarn, fmt.Sprintf(format, params...)) } // Errorf creates a formatted message from the to format specifier along with @@ -78,7 +117,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.level.Load() > int64(levelError) { + return + } + + l.logger.Log(l.unusedCtx, levelError, fmt.Sprintf(format, params...)) } // Criticalf creates a formatted message from the to format specifier along @@ -86,7 +129,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.level.Load() > int64(levelCritical) { + return + } + + l.logger.Log(l.unusedCtx, levelCritical, fmt.Sprintf(format, params...)) } // Trace formats a message using the default formats for its operands, prepends @@ -94,7 +141,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.level.Load() > int64(levelTrace) { + return + } + + l.logger.Log(l.unusedCtx, levelTrace, fmt.Sprint(v...)) } // Debug formats a message using the default formats for its operands, prepends @@ -102,7 +153,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.level.Load() > int64(levelDebug) { + return + } + + l.logger.Log(l.unusedCtx, levelDebug, fmt.Sprint(v...)) } // Info formats a message using the default formats for its operands, prepends @@ -110,7 +165,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.level.Load() > int64(levelInfo) { + return + } + + l.logger.Log(l.unusedCtx, levelInfo, fmt.Sprint(v...)) } // Warn formats a message using the default formats for its operands, prepends @@ -118,7 +177,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.level.Load() > int64(levelWarn) { + return + } + + l.logger.Log(l.unusedCtx, levelWarn, fmt.Sprint(v...)) } // Error formats a message using the default formats for its operands, prepends @@ -126,7 +189,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.level.Load() > int64(levelError) { + return + } + + l.logger.Log(l.unusedCtx, levelError, fmt.Sprint(v...)) } // Critical formats a message using the default formats for its operands, @@ -134,7 +201,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.level.Load() > int64(levelCritical) { + return + } + + l.logger.Log(l.unusedCtx, levelCritical, fmt.Sprint(v...)) } // TraceS writes a structured log with the given message and key-value pair @@ -142,7 +213,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.level.Load() > int64(levelTrace) { + return + } + + l.logger.Log(ctx, levelTrace, msg, mergeAttrs(ctx, attrs)...) } // DebugS writes a structured log with the given message and key-value pair @@ -150,7 +225,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.level.Load() > int64(levelDebug) { + return + } + + l.logger.Log(ctx, levelDebug, msg, mergeAttrs(ctx, attrs)...) } // InfoS writes a structured log with the given message and key-value pair @@ -158,7 +237,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.level.Load() > int64(levelInfo) { + return + } + + l.logger.Log(ctx, levelInfo, msg, mergeAttrs(ctx, attrs)...) } // WarnS writes a structured log with the given message and key-value pair @@ -168,11 +251,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.level.Load() > int64(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 @@ -182,11 +269,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.level.Load() > int64(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 @@ -195,34 +286,47 @@ 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 l.level.Load() > int64(levelCritical) { + return + } + if err != nil { attrs = append([]any{slog.String("err", err.Error())}, attrs...) } - l.toSlogS(ctx, levelCritical, msg, attrs...) + l.logger.Log(ctx, levelCritical, msg, mergeAttrs(ctx, 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) { - l.logger.Log(context.Background(), level, - fmt.Sprintf(format, params...)) +// 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())) } -// 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...)) +// 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) } -// 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) { +// 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)) +} - l.logger.Log(ctx, level, msg, mergeAttrs(ctx, attrs)...) +// 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) 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)) + } + }) + } +}