diff --git a/.travis.yml b/.travis.yml deleted file mode 100644 index e1e3198..0000000 --- a/.travis.yml +++ /dev/null @@ -1,13 +0,0 @@ -language: go -go: - - 1.7.x - - 1.8.x -sudo: false -install: - - go get -d -t -v ./... - - go get -v golang.org/x/tools/cmd/cover - - go get -v github.com/bradfitz/goimports - - go get -v github.com/golang/lint/golint -script: - - export PATH=$PATH:$HOME/gopath/bin - - ./goclean.sh diff --git a/attrs.go b/attrs.go new file mode 100644 index 0000000..0b6f1fc --- /dev/null +++ b/attrs.go @@ -0,0 +1,36 @@ +package btclog + +import ( + "context" + "encoding/hex" + "log/slog" +) + +// Hex is a convenience function for a hex-encoded log attributes. +func Hex(key string, value []byte) slog.Attr { + h := hex.EncodeToString(value) + + return slog.String(key, h) +} + +type attrsKey struct{} + +// WithCtx returns a copy of the context with which the logging attributes are +// associated. +// +// Usage: +// +// ctx := log.WithCtx(ctx, "height", 1234) +// ... +// log.Info(ctx, "Height processed") // Will contain attribute: height=1234 +func WithCtx(ctx context.Context, attrs ...any) context.Context { + return context.WithValue(ctx, attrsKey{}, mergeAttrs(ctx, attrs)) +} + +// mergeAttrs returns the attributes from the context merged with the provided attributes. +func mergeAttrs(ctx context.Context, attrs []any) []any { + resp, _ := ctx.Value(attrsKey{}).([]any) // We know the type. + resp = append(resp, attrs...) + + return resp +} diff --git a/buffer.go b/buffer.go new file mode 100644 index 0000000..4797113 --- /dev/null +++ b/buffer.go @@ -0,0 +1,51 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +// Adapted from go/src/log/slog/internal/buffer.go + +package btclog + +import "sync" + +type buffer []byte + +// bufferPool defines a concurrent safe free list of byte slices used to provide +// temporary buffers for formatting log messages prior to outputting them. +var bufferPool = sync.Pool{ + New: func() any { + b := make([]byte, 0, 1024) + return (*buffer)(&b) + }, +} + +// newBuffer returns a byte slice from the free list. A new buffer is allocated +// if there are not any available on the free list. The returned byte slice +// should be returned to the fee list by using the recycleBuffer function when +// the caller is done with it. +func newBuffer() *buffer { + return bufferPool.Get().(*buffer) +} + +// free puts the provided byte slice, which should have been obtained via the +// newBuffer function, back on the free list. +func (b *buffer) free() { + // To reduce peak allocation, return only smaller buffers to the pool. + const maxBufferSize = 16 << 10 + if cap(*b) <= maxBufferSize { + *b = (*b)[:0] + bufferPool.Put(b) + } +} + +func (b *buffer) writeByte(p byte) { + *b = append(*b, p) +} + +func (b *buffer) writeBytes(p []byte) { + *b = append(*b, p...) +} + +func (b *buffer) writeString(s string) { + *b = append(*b, s...) +} diff --git a/go.mod b/go.mod new file mode 100644 index 0000000..4ac3359 --- /dev/null +++ b/go.mod @@ -0,0 +1,3 @@ +module github.com/lightninglabs/btclog + +go 1.21 diff --git a/handler.go b/handler.go new file mode 100644 index 0000000..aa64523 --- /dev/null +++ b/handler.go @@ -0,0 +1,474 @@ +package btclog + +import ( + "context" + "fmt" + "io" + "log/slog" + "strconv" + "strings" + "sync" + "sync/atomic" + "time" + "unicode" + "unicode/utf8" +) + +const ( + resetSeq = "0" + boldSeq = "1" + faintSeq = "2" + + esc = '\x1b' + csi = string(esc) + "[" +) + +// HandlerOption is the signature of a functional option that can be used to +// modify the behaviour of the DefaultHandler. +type HandlerOption func(*handlerOpts) + +// handlerOpts holds options that can be modified by a HandlerOption. +type handlerOpts struct { + flag uint32 + withTimestamp bool + styled bool + timeSource func() time.Time +} + +// defaultHandlerOpts constructs a handlerOpts with default settings. +func defaultHandlerOpts() *handlerOpts { + return &handlerOpts{ + flag: defaultFlags, + withTimestamp: true, + styled: false, + } +} + +// WithTimeSource can be used to overwrite the time sourced from the slog +// Record. +func WithTimeSource(fn func() time.Time) HandlerOption { + return func(opts *handlerOpts) { + opts.timeSource = fn + } +} + +// WithCallerFlags can be used to overwrite the default caller flag option. +func WithCallerFlags(flags uint32) HandlerOption { + return func(b *handlerOpts) { + b.flag = flags + } +} + +// WithStyledOutput can be used to add additional styling to the logs. This +// currently includes colored & bold tags and faint fonts for attribute keys and +// callsites. +func WithStyledOutput() HandlerOption { + return func(opts *handlerOpts) { + opts.styled = true + } +} + +// WithNoTimestamp is an option that can be used to omit timestamps from the log +// lines. +func WithNoTimestamp() HandlerOption { + return func(opts *handlerOpts) { + opts.withTimestamp = false + } +} + +// DefaultHandler is a Handler that can be used along with NewSLogger to +// instantiate a structured logger. +type DefaultHandler struct { + opts *handlerOpts + + level int64 + tag string + fields []slog.Attr + callstackOffset bool + + flag uint32 + buf *buffer + mu *sync.Mutex + w io.Writer +} + +// A compile-time check to ensure that DefaultHandler implements Handler. +var _ Handler = (*DefaultHandler)(nil) + +// Level returns the current logging level of the Handler. +// +// NOTE: This is part of the Handler interface. +func (d *DefaultHandler) Level() Level { + return Level(atomic.LoadInt64(&d.level)) +} + +// SetLevel changes the logging level of the Handler to the passed +// level. +// +// NOTE: This is part of the Handler interface. +func (d *DefaultHandler) SetLevel(level Level) { + atomic.StoreInt64(&d.level, int64(level)) +} + +// NewDefaultHandler creates a new Handler that can be used along with +// NewSLogger to instantiate a structured logger. +func NewDefaultHandler(w io.Writer, options ...HandlerOption) *DefaultHandler { + opts := defaultHandlerOpts() + for _, o := range options { + o(opts) + } + + return &DefaultHandler{ + w: w, + level: int64(LevelInfo), + opts: opts, + buf: newBuffer(), + mu: &sync.Mutex{}, + } +} + +// Enabled reports whether the handler handles records at the given level. +// +// NOTE: this is part of the slog.Handler interface. +func (d *DefaultHandler) Enabled(_ context.Context, level slog.Level) bool { + return atomic.LoadInt64(&d.level) <= int64(level) +} + +// Handle handles the Record. It will only be called if Enabled returns true. +// +// NOTE: this is part of the slog.Handler interface. +func (d *DefaultHandler) Handle(_ context.Context, r slog.Record) error { + buf := newBuffer() + defer buf.free() + + // Timestamp. + if d.opts.withTimestamp { + // First check if the options provided specified a different + // time source to use. Otherwise, use the provided record time. + if d.opts.timeSource != nil { + writeTimestamp(buf, d.opts.timeSource()) + } else if !r.Time.IsZero() { + writeTimestamp(buf, r.Time) + } + } + + // Level. + d.writeLevel(buf, Level(r.Level)) + + // Sub-system tag. + if d.tag != "" { + buf.writeString(" " + d.tag) + } + + // The call-site. + if d.opts.flag&(Lshortfile|Llongfile) != 0 { + skip := 6 + if d.callstackOffset { + skip = 4 + } + file, line := callsite(d.opts.flag, skip) + d.writeCallSite(buf, file, line) + } + + // Finish off the header. + buf.writeString(": ") + + // Write the log message itself. + if r.Message != "" { + buf.writeString(r.Message) + } + + // Append logger fields. + for _, attr := range d.fields { + d.appendAttr(buf, attr) + } + + // Append slog attributes. + r.Attrs(func(a slog.Attr) bool { + d.appendAttr(buf, a) + return true + }) + buf.writeByte('\n') + + d.mu.Lock() + defer d.mu.Unlock() + _, err := d.w.Write(*buf) + + return err +} + +// WithAttrs returns a new Handler with the given attributes added. +// +// 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...) +} + +// WithGroup returns a new Handler with the given group appended to +// the receiver's existing groups. All this implementation does is add to the +// existing tag used for the logger. +// +// NOTE: this is part of the slog.Handler interface. +func (d *DefaultHandler) WithGroup(name string) slog.Handler { + if d.tag != "" { + name = d.tag + "." + name + } + return d.with(name, 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. +func (d *DefaultHandler) SubSystem(tag string) Handler { + return d.with(tag, 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, + attrs ...slog.Attr) *DefaultHandler { + + d.mu.Lock() + sl := *d + d.mu.Unlock() + sl.buf = newBuffer() + + sl.mu = &sync.Mutex{} + sl.fields = append( + make([]slog.Attr, 0, len(d.fields)+len(attrs)), d.fields..., + ) + sl.fields = append(sl.fields, attrs...) + sl.callstackOffset = withCallstackOffset + sl.tag = tag + + return &sl +} + +func (d *DefaultHandler) styleString(s string, styles ...string) string { + if !d.opts.styled { + return s + } + + if len(styles) == 0 { + return s + } + + seq := strings.Join(styles, ";") + if seq == "" { + return s + } + + return fmt.Sprintf("%s%sm%s%sm", csi, seq, s, csi+resetSeq) +} + +func (d *DefaultHandler) appendAttr(buf *buffer, a slog.Attr) { + // Resolve the Attr's value before doing anything else. + a.Value = a.Value.Resolve() + + // Ignore empty Attrs. + if a.Equal(slog.Attr{}) { + return + } + + d.appendKey(buf, a.Key) + appendValue(buf, a.Value) +} + +func (d *DefaultHandler) writeLevel(buf *buffer, level Level) { + str := fmt.Sprintf("[%s]", level) + + buf.writeString(d.styleString( + str, boldSeq, string(level.ansiColoSeq())), + ) +} + +func (d *DefaultHandler) writeCallSite(buf *buffer, file string, line int) { + if file == "" { + return + } + + buf.writeString( + d.styleString(fmt.Sprintf(" %s:%d", file, line), faintSeq), + ) +} + +func appendString(buf *buffer, str string) { + if needsQuoting(str) { + *buf = strconv.AppendQuote(*buf, str) + } else { + buf.writeString(str) + } +} + +func (d *DefaultHandler) appendKey(buf *buffer, key string) { + buf.writeString(" ") + if needsQuoting(key) { + key = strconv.Quote(key) + } + key += "=" + + buf.writeString(d.styleString(key, faintSeq)) +} + +func appendValue(buf *buffer, v slog.Value) { + defer func() { + // Recovery in case of nil pointer dereferences. + if r := recover(); r != nil { + // Catch any panics that are most likely due to nil + // pointers. + appendString(buf, fmt.Sprintf("!PANIC: %v", r)) + } + }() + + appendTextValue(buf, v) +} + +func appendTextValue(buf *buffer, v slog.Value) { + switch v.Kind() { + case slog.KindString: + appendString(buf, v.String()) + case slog.KindAny: + appendString(buf, fmt.Sprintf("%+v", v.Any())) + default: + appendString(buf, fmt.Sprintf("%s", v)) + } +} + +// Copied from log/slog/text_handler.go. +// +// needsQuoting returns true if the given strings should be wrapped in quotes. +func needsQuoting(s string) bool { + if len(s) == 0 { + return true + } + for i := 0; i < len(s); { + b := s[i] + if b < utf8.RuneSelf { + // Quote anything except a backslash that would need + // quoting in a JSON string, as well as space and '='. + if b != '\\' && (b == ' ' || b == '=' || !safeSet[b]) { + return true + } + i++ + continue + } + r, size := utf8.DecodeRuneInString(s[i:]) + if r == utf8.RuneError || unicode.IsSpace(r) || + !unicode.IsPrint(r) { + + return true + } + i += size + } + return false +} + +// Copied from encoding/json/tables.go. +// +// safeSet holds the value true if the ASCII character with the given array +// position can be represented inside a JSON string without any further +// escaping. +// +// All values are true except for the ASCII control characters (0-31), the +// double quote ("), and the backslash character ("\"). +var safeSet = [utf8.RuneSelf]bool{ + ' ': true, + '!': true, + '"': false, + '#': true, + '$': true, + '%': true, + '&': true, + '\'': true, + '(': true, + ')': true, + '*': true, + '+': true, + ',': true, + '-': true, + '.': true, + '/': true, + '0': true, + '1': true, + '2': true, + '3': true, + '4': true, + '5': true, + '6': true, + '7': true, + '8': true, + '9': true, + ':': true, + ';': true, + '<': true, + '=': true, + '>': true, + '?': true, + '@': true, + 'A': true, + 'B': true, + 'C': true, + 'D': true, + 'E': true, + 'F': true, + 'G': true, + 'H': true, + 'I': true, + 'J': true, + 'K': true, + 'L': true, + 'M': true, + 'N': true, + 'O': true, + 'P': true, + 'Q': true, + 'R': true, + 'S': true, + 'T': true, + 'U': true, + 'V': true, + 'W': true, + 'X': true, + 'Y': true, + 'Z': true, + '[': true, + '\\': false, + ']': true, + '^': true, + '_': true, + '`': true, + 'a': true, + 'b': true, + 'c': true, + 'd': true, + 'e': true, + 'f': true, + 'g': true, + 'h': true, + 'i': true, + 'j': true, + 'k': true, + 'l': true, + 'm': true, + 'n': true, + 'o': true, + 'p': true, + 'q': true, + 'r': true, + 's': true, + 't': true, + 'u': true, + 'v': true, + 'w': true, + 'x': true, + 'y': true, + 'z': true, + '{': true, + '|': true, + '}': true, + '~': true, + '\u007f': true, +} diff --git a/handler_test.go b/handler_test.go new file mode 100644 index 0000000..c7183bb --- /dev/null +++ b/handler_test.go @@ -0,0 +1,155 @@ +package btclog + +import ( + "bytes" + "context" + "errors" + "io" + "testing" + "time" +) + +// TestDefaultHandler tests that the DefaultHandler's output looks as expected. +func TestDefaultHandler(t *testing.T) { + t.Parallel() + + // Set time zone explicitly to keep test deterministic. + time.Local = time.UTC + + timeSource := func() time.Time { + return time.Unix(100, 100) + } + + tests := []struct { + name string + handlerConstructor func(w io.Writer) Handler + logFunc func(log Logger) + expectedLog string + }{ + { + name: "Basic calls and levels", + handlerConstructor: func(w io.Writer) Handler { + h := NewDefaultHandler( + w, WithTimeSource(timeSource), + ) + h.SetLevel(LevelDebug) + return h + }, + 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 00:01:40.000 [INF]: Test Basic Log +1970-01-01 00:01:40.000 [DBG]: Test basic log with format +`, + }, + { + name: "Sub-system tag", + handlerConstructor: func(w io.Writer) Handler { + h := NewDefaultHandler(w, WithNoTimestamp()) + return h.SubSystem("SUBS") + }, + logFunc: func(log Logger) { + log.Info("Test Basic Log") + }, + expectedLog: `[INF] SUBS: Test Basic Log +`, + }, + { + name: "Test all levels", + handlerConstructor: func(w io.Writer) Handler { + h := NewDefaultHandler(w, WithNoTimestamp()) + h.SetLevel(LevelTrace) + return h + }, + 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()) + }, + 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 +[INF]: Single word attribute key=value +[INF]: Multi word string value "key with spaces"=value +[INF]: Number attribute key=5 +[INF]: Bad key !BADKEY=key +[INF]: Nil pointer value key= +[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()) + }, + 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") + }, + 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" +[ERR]: Structured error 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) + + 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()) + } + }) + } +} diff --git a/interface.go b/interface.go index 64f74fc..2a18a57 100644 --- a/interface.go +++ b/interface.go @@ -4,57 +4,83 @@ package btclog +import "context" + // Logger is an interface which describes a level-based logger. A default // implementation of Logger is implemented by this package and can be created // by calling (*Backend).Logger. type Logger interface { // Tracef formats message according to format specifier and writes to // to log with LevelTrace. - Tracef(format string, params ...interface{}) + Tracef(format string, params ...any) // Debugf formats message according to format specifier and writes to // log with LevelDebug. - Debugf(format string, params ...interface{}) + Debugf(format string, params ...any) // Infof formats message according to format specifier and writes to // log with LevelInfo. - Infof(format string, params ...interface{}) + Infof(format string, params ...any) // Warnf formats message according to format specifier and writes to // to log with LevelWarn. - Warnf(format string, params ...interface{}) + Warnf(format string, params ...any) // Errorf formats message according to format specifier and writes to // to log with LevelError. - Errorf(format string, params ...interface{}) + Errorf(format string, params ...any) // Criticalf formats message according to format specifier and writes to // log with LevelCritical. - Criticalf(format string, params ...interface{}) + Criticalf(format string, params ...any) // Trace formats message using the default formats for its operands // and writes to log with LevelTrace. - Trace(v ...interface{}) + Trace(v ...any) // Debug formats message using the default formats for its operands // and writes to log with LevelDebug. - Debug(v ...interface{}) + Debug(v ...any) // Info formats message using the default formats for its operands // and writes to log with LevelInfo. - Info(v ...interface{}) + Info(v ...any) // Warn formats message using the default formats for its operands // and writes to log with LevelWarn. - Warn(v ...interface{}) + Warn(v ...any) // Error formats message using the default formats for its operands // and writes to log with LevelError. - Error(v ...interface{}) + Error(v ...any) // Critical formats message using the default formats for its operands // and writes to log with LevelCritical. - Critical(v ...interface{}) + Critical(v ...any) + + // TraceS writes a structured log with the given message and key-value + // pair attributes with LevelTrace to the log. + TraceS(ctx context.Context, msg string, attrs ...any) + + // DebugS writes a structured log with the given message and key-value + // pair attributes with LevelDebug to the log. + DebugS(ctx context.Context, msg string, attrs ...any) + + // InfoS writes a structured log with the given message and key-value + // pair attributes with LevelInfo to the log. + InfoS(ctx context.Context, msg string, attrs ...any) + + // WarnS writes a structured log with the given message and key-value + // pair attributes with LevelWarn to the log. + WarnS(ctx context.Context, msg string, err error, attrs ...any) + + // ErrorS writes a structured log with the given message and key-value + // pair attributes with LevelError to the log. + ErrorS(ctx context.Context, msg string, err error, attrs ...any) + + // CriticalS writes a structured log with the given message and + // key-value pair attributes with LevelCritical to the log. + CriticalS(ctx context.Context, msg string, err error, attrs ...any) // Level returns the current logging level. Level() Level diff --git a/level.go b/level.go new file mode 100644 index 0000000..b840ebb --- /dev/null +++ b/level.go @@ -0,0 +1,110 @@ +package btclog + +import ( + "fmt" + "log/slog" + "strings" +) + +// Level is the level at which a logger is configured. All messages sent +// to a level which is below the current level are filtered. +type Level slog.Level + +// Level constants. +// Names for common levels. +const ( + LevelTrace Level = -5 + LevelDebug = Level(slog.LevelDebug) + LevelInfo = Level(slog.LevelInfo) + LevelWarn = Level(slog.LevelWarn) + LevelError = Level(slog.LevelError) + LevelCritical Level = 9 + LevelOff Level = 10 +) + +// LevelFromString returns a level based on the input string s. If the input +// can't be interpreted as a valid log level, the info level and false is +// returned. +func LevelFromString(s string) (l Level, ok bool) { + switch strings.ToLower(s) { + case "trace", "trc": + return LevelTrace, true + case "debug", "dbg": + return LevelDebug, true + case "info", "inf": + return LevelInfo, true + case "warn", "wrn": + return LevelWarn, true + case "error", "err": + return LevelError, true + case "critical", "crt": + return LevelCritical, true + case "off": + return LevelOff, true + default: + return LevelInfo, false + } +} + +// String returns a name for the level. If the level has a name, then that name +// in uppercase is returned. If the level is between named values, then an +// integer is appended to the uppercase name. +// Examples: +// +// LevelWarn.String() => "WARN" +// (LevelInfo+2).String() => "INFO+2" +func (l Level) String() string { + if l >= LevelOff { + return "OFF" + } + + str := func(base string, val Level) string { + if val == 0 { + return base + } + return fmt.Sprintf("%s%+d", base, val) + } + + switch { + case l < LevelDebug: + return str("TRC", l-LevelTrace) + case l < LevelInfo: + return str("DBG", l-LevelDebug) + case l < LevelWarn: + return str("INF", l-LevelInfo) + case l < LevelError: + return str("WRN", l-LevelWarn) + case l < LevelCritical: + return str("ERR", l-LevelError) + default: + return str("CRT", l-LevelCritical) + } +} + +type ansiColorSeq string + +const ( + ansiColorSeqDarkTeal ansiColorSeq = "38;5;30" + ansiColorSeqDarkBlue ansiColorSeq = "38;5;63" + ansiColorSeqLightBlue ansiColorSeq = "38;5;86" + ansiColorSeqYellow ansiColorSeq = "38;5;192" + ansiColorSeqRed ansiColorSeq = "38;5;204" + ansiColorSeqPink ansiColorSeq = "38;5;134" +) + +func (l Level) ansiColoSeq() ansiColorSeq { + switch l { + case LevelTrace: + return ansiColorSeqDarkTeal + case LevelDebug: + return ansiColorSeqDarkBlue + case LevelWarn: + return ansiColorSeqYellow + case LevelError: + return ansiColorSeqRed + case LevelCritical: + return ansiColorSeqPink + default: + return ansiColorSeqLightBlue + } +} diff --git a/log.go b/log.go index d8f3dcd..b9bd1c7 100644 --- a/log.go +++ b/log.go @@ -34,9 +34,10 @@ package btclog import ( "bytes" + "context" "fmt" "io" - "io/ioutil" + "log/slog" "os" "runtime" "strings" @@ -74,57 +75,6 @@ func init() { } } -// Level is the level at which a logger is configured. All messages sent -// to a level which is below the current level are filtered. -type Level uint32 - -// Level constants. -const ( - LevelTrace Level = iota - LevelDebug - LevelInfo - LevelWarn - LevelError - LevelCritical - LevelOff -) - -// levelStrs defines the human-readable names for each logging level. -var levelStrs = [...]string{"TRC", "DBG", "INF", "WRN", "ERR", "CRT", "OFF"} - -// LevelFromString returns a level based on the input string s. If the input -// can't be interpreted as a valid log level, the info level and false is -// returned. -func LevelFromString(s string) (l Level, ok bool) { - switch strings.ToLower(s) { - case "trace", "trc": - return LevelTrace, true - case "debug", "dbg": - return LevelDebug, true - case "info", "inf": - return LevelInfo, true - case "warn", "wrn": - return LevelWarn, true - case "error", "err": - return LevelError, true - case "critical", "crt": - return LevelCritical, true - case "off": - return LevelOff, true - default: - return LevelInfo, false - } -} - -// String returns the tag of the logger used in log messages, or "OFF" if -// the level will not produce any log output. -func (l Level) String() string { - if l >= LevelOff { - return "OFF" - } - return levelStrs[l] -} - // NewBackend creates a logger backend from a Writer. func NewBackend(w io.Writer, opts ...BackendOption) *Backend { b := &Backend{w: w, flag: defaultFlags} @@ -155,34 +105,10 @@ func WithFlags(flags uint32) BackendOption { } } -// bufferPool defines a concurrent safe free list of byte slices used to provide -// temporary buffers for formatting log messages prior to outputting them. -var bufferPool = sync.Pool{ - New: func() interface{} { - b := make([]byte, 0, 120) - return &b // pointer to slice to avoid boxing alloc - }, -} - -// buffer returns a byte slice from the free list. A new buffer is allocated if -// there are not any available on the free list. The returned byte slice should -// be returned to the fee list by using the recycleBuffer function when the -// caller is done with it. -func buffer() *[]byte { - return bufferPool.Get().(*[]byte) -} - -// recycleBuffer puts the provided byte slice, which should have been obtain via -// the buffer function, back on the free list. -func recycleBuffer(b *[]byte) { - *b = (*b)[:0] - bufferPool.Put(b) -} - // From stdlib log package. // Cheap integer to fixed-width decimal ASCII. Give a negative width to avoid // zero-padding. -func itoa(buf *[]byte, i int, wid int) { +func itoa(buf *buffer, i int, wid int) { // Assemble decimal in reverse order. var b [20]byte bp := len(b) - 1 @@ -195,30 +121,15 @@ func itoa(buf *[]byte, i int, wid int) { } // i < 10 b[bp] = byte('0' + i) - *buf = append(*buf, b[bp:]...) + buf.writeBytes(b[bp:]) } // Appends a header in the default format 'YYYY-MM-DD hh:mm:ss.sss [LVL] TAG: '. // If either of the Lshortfile or Llongfile flags are specified, the file named // and line number are included after the tag and before the final colon. -func formatHeader(buf *[]byte, t time.Time, lvl, tag string, file string, line int) { - year, month, day := t.Date() - hour, min, sec := t.Clock() - ms := t.Nanosecond() / 1e6 +func formatHeader(buf *buffer, t time.Time, lvl, tag string, file string, line int) { + writeTimestamp(buf, t) - itoa(buf, year, 4) - *buf = append(*buf, '-') - itoa(buf, int(month), 2) - *buf = append(*buf, '-') - itoa(buf, day, 2) - *buf = append(*buf, ' ') - itoa(buf, hour, 2) - *buf = append(*buf, ':') - itoa(buf, min, 2) - *buf = append(*buf, ':') - itoa(buf, sec, 2) - *buf = append(*buf, '.') - itoa(buf, ms, 3) *buf = append(*buf, " ["...) *buf = append(*buf, lvl...) *buf = append(*buf, "] "...) @@ -232,6 +143,29 @@ func formatHeader(buf *[]byte, t time.Time, lvl, tag string, file string, line i *buf = append(*buf, ": "...) } +// writeTimestamp writes the date in the format 'YYYY-MM-DD hh:mm:ss.sss' to the +// buffer. +func writeTimestamp(buf *buffer, t time.Time) { + year, month, day := t.Date() + hour, min, sec := t.Clock() + ms := t.Nanosecond() / 1e6 + + itoa(buf, year, 4) + buf.writeByte('-') + itoa(buf, int(month), 2) + buf.writeByte('-') + itoa(buf, day, 2) + buf.writeByte(' ') + itoa(buf, hour, 2) + buf.writeByte(':') + itoa(buf, min, 2) + buf.writeByte(':') + itoa(buf, sec, 2) + buf.writeByte('.') + itoa(buf, ms, 3) + buf.writeByte(' ') +} + // calldepth is the call depth of the callsite function relative to the // caller of the subsystem logger. It is used to recover the filename and line // number of the logging call if either the short or long file flags are @@ -240,8 +174,8 @@ const calldepth = 3 // callsite returns the file name and line number of the callsite to the // subsystem logger. -func callsite(flag uint32) (string, int) { - _, file, line, ok := runtime.Caller(calldepth) +func callsite(flag uint32, skipDepth int) (string, int) { + _, file, line, ok := runtime.Caller(skipDepth) if !ok { return "???", 0 } @@ -262,15 +196,15 @@ func callsite(flag uint32) (string, int) { // creating a prefix for the given level and tag according to the formatHeader // function and formatting the provided arguments using the default formatting // rules. -func (b *Backend) print(lvl, tag string, args ...interface{}) { +func (b *Backend) print(lvl, tag string, args ...any) { t := time.Now() // get as early as possible - bytebuf := buffer() + bytebuf := newBuffer() var file string var line int if b.flag&(Lshortfile|Llongfile) != 0 { - file, line = callsite(b.flag) + file, line = callsite(b.flag, calldepth) } formatHeader(bytebuf, t, lvl, tag, file, line) @@ -282,22 +216,22 @@ func (b *Backend) print(lvl, tag string, args ...interface{}) { b.w.Write(*bytebuf) b.mu.Unlock() - recycleBuffer(bytebuf) + bytebuf.free() } // printf outputs a log message to the writer associated with the backend after // creating a prefix for the given level and tag according to the formatHeader // function and formatting the provided arguments according to the given format // specifier. -func (b *Backend) printf(lvl, tag string, format string, args ...interface{}) { +func (b *Backend) printf(lvl, tag string, format string, args ...any) { t := time.Now() // get as early as possible - bytebuf := buffer() + bytebuf := newBuffer() var file string var line int if b.flag&(Lshortfile|Llongfile) != 0 { - file, line = callsite(b.flag) + file, line = callsite(b.flag, calldepth) } formatHeader(bytebuf, t, lvl, tag, file, line) @@ -309,28 +243,39 @@ func (b *Backend) printf(lvl, tag string, format string, args ...interface{}) { b.w.Write(*bytebuf) b.mu.Unlock() - recycleBuffer(bytebuf) + bytebuf.free() } // Logger returns a new logger for a particular subsystem that writes to the // Backend b. A tag describes the subsystem and is included in all log // messages. The logger uses the info verbosity level by default. func (b *Backend) Logger(subsystemTag string) Logger { - return &slog{LevelInfo, subsystemTag, b} + return newSubLog(subsystemTag, b, LevelInfo) } -// slog is a subsystem logger for a Backend. Implements the Logger interface. -type slog struct { - lvl Level // atomic +// subLog is a subsystem logger for a Backend. Implements the Logger interface. +type subLog struct { + lvl atomic.Int32 tag string b *Backend } +// newSubLog constructs a new subLog instance. +func newSubLog(tag string, b *Backend, level Level) *subLog { + s := &subLog{ + tag: tag, + b: b, + } + s.lvl.Store(int32(level)) + + return s +} + // Trace formats message using the default formats for its operands, prepends // the prefix as necessary, and writes to log with LevelTrace. // // This is part of the Logger interface implementation. -func (l *slog) Trace(args ...interface{}) { +func (l *subLog) Trace(args ...any) { lvl := l.Level() if lvl <= LevelTrace { l.b.print("TRC", l.tag, args...) @@ -341,7 +286,7 @@ func (l *slog) Trace(args ...interface{}) { // necessary, and writes to log with LevelTrace. // // This is part of the Logger interface implementation. -func (l *slog) Tracef(format string, args ...interface{}) { +func (l *subLog) Tracef(format string, args ...any) { lvl := l.Level() if lvl <= LevelTrace { l.b.printf("TRC", l.tag, format, args...) @@ -352,7 +297,7 @@ func (l *slog) Tracef(format string, args ...interface{}) { // the prefix as necessary, and writes to log with LevelDebug. // // This is part of the Logger interface implementation. -func (l *slog) Debug(args ...interface{}) { +func (l *subLog) Debug(args ...any) { lvl := l.Level() if lvl <= LevelDebug { l.b.print("DBG", l.tag, args...) @@ -363,7 +308,7 @@ func (l *slog) Debug(args ...interface{}) { // necessary, and writes to log with LevelDebug. // // This is part of the Logger interface implementation. -func (l *slog) Debugf(format string, args ...interface{}) { +func (l *subLog) Debugf(format string, args ...any) { lvl := l.Level() if lvl <= LevelDebug { l.b.printf("DBG", l.tag, format, args...) @@ -374,7 +319,7 @@ func (l *slog) Debugf(format string, args ...interface{}) { // the prefix as necessary, and writes to log with LevelInfo. // // This is part of the Logger interface implementation. -func (l *slog) Info(args ...interface{}) { +func (l *subLog) Info(args ...any) { lvl := l.Level() if lvl <= LevelInfo { l.b.print("INF", l.tag, args...) @@ -385,7 +330,7 @@ func (l *slog) Info(args ...interface{}) { // necessary, and writes to log with LevelInfo. // // This is part of the Logger interface implementation. -func (l *slog) Infof(format string, args ...interface{}) { +func (l *subLog) Infof(format string, args ...any) { lvl := l.Level() if lvl <= LevelInfo { l.b.printf("INF", l.tag, format, args...) @@ -396,7 +341,7 @@ func (l *slog) Infof(format string, args ...interface{}) { // the prefix as necessary, and writes to log with LevelWarn. // // This is part of the Logger interface implementation. -func (l *slog) Warn(args ...interface{}) { +func (l *subLog) Warn(args ...any) { lvl := l.Level() if lvl <= LevelWarn { l.b.print("WRN", l.tag, args...) @@ -407,7 +352,7 @@ func (l *slog) Warn(args ...interface{}) { // necessary, and writes to log with LevelWarn. // // This is part of the Logger interface implementation. -func (l *slog) Warnf(format string, args ...interface{}) { +func (l *subLog) Warnf(format string, args ...any) { lvl := l.Level() if lvl <= LevelWarn { l.b.printf("WRN", l.tag, format, args...) @@ -418,7 +363,7 @@ func (l *slog) Warnf(format string, args ...interface{}) { // the prefix as necessary, and writes to log with LevelError. // // This is part of the Logger interface implementation. -func (l *slog) Error(args ...interface{}) { +func (l *subLog) Error(args ...any) { lvl := l.Level() if lvl <= LevelError { l.b.print("ERR", l.tag, args...) @@ -429,7 +374,7 @@ func (l *slog) Error(args ...interface{}) { // necessary, and writes to log with LevelError. // // This is part of the Logger interface implementation. -func (l *slog) Errorf(format string, args ...interface{}) { +func (l *subLog) Errorf(format string, args ...any) { lvl := l.Level() if lvl <= LevelError { l.b.printf("ERR", l.tag, format, args...) @@ -440,7 +385,7 @@ func (l *slog) Errorf(format string, args ...interface{}) { // the prefix as necessary, and writes to log with LevelCritical. // // This is part of the Logger interface implementation. -func (l *slog) Critical(args ...interface{}) { +func (l *subLog) Critical(args ...any) { lvl := l.Level() if lvl <= LevelCritical { l.b.print("CRT", l.tag, args...) @@ -451,30 +396,87 @@ func (l *slog) Critical(args ...interface{}) { // as necessary, and writes to log with LevelCritical. // // This is part of the Logger interface implementation. -func (l *slog) Criticalf(format string, args ...interface{}) { +func (l *subLog) Criticalf(format string, args ...any) { lvl := l.Level() if lvl <= LevelCritical { l.b.printf("CRT", l.tag, format, args...) } } +// TraceS writes a structured log with the given message and key-value pair +// attributes with LevelTrace to the log. +// +// This is part of the Logger interface implementation. +func (l *subLog) TraceS(_ context.Context, msg string, attrs ...any) { + l.Tracef(msg, attrs...) +} + +// DebugS writes a structured log with the given message and key-value pair +// attributes with LevelDebug to the log. +// +// This is part of the Logger interface implementation. +func (l *subLog) DebugS(_ context.Context, msg string, attrs ...any) { + l.Debugf(msg, attrs...) +} + +// InfoS writes a structured log with the given message and key-value pair +// attributes with LevelInfo to the log. +// +// This is part of the Logger interface implementation. +func (l *subLog) InfoS(_ context.Context, msg string, attrs ...any) { + l.Infof(msg, attrs...) +} + +// WarnS writes a structured log with the given message and key-value pair +// attributes with LevelWarn to the log. +// +// This is part of the Logger interface implementation. +func (l *subLog) WarnS(_ context.Context, msg string, err error, attrs ...any) { + if err != nil { + attrs = append([]any{slog.String("err", err.Error())}, attrs...) + } + l.Warnf(msg, attrs...) +} + +// ErrorS writes a structured log with the given message and key-value pair +// attributes with LevelError to the log. +// +// This is part of the Logger interface implementation. +func (l *subLog) ErrorS(_ context.Context, msg string, err error, attrs ...any) { + if err != nil { + attrs = append([]any{slog.String("err", err.Error())}, attrs...) + } + l.Errorf(msg, attrs...) +} + +// CriticalS writes a structured log with the given message and key-value pair +// attributes with LevelCritical to the log. +// +// This is part of the Logger interface implementation. +func (l *subLog) CriticalS(_ context.Context, msg string, err error, attrs ...any) { + if err != nil { + attrs = append([]any{slog.String("err", err.Error())}, attrs...) + } + l.Criticalf(msg, attrs...) +} + // Level returns the current logging level // // This is part of the Logger interface implementation. -func (l *slog) Level() Level { - return Level(atomic.LoadUint32((*uint32)(&l.lvl))) +func (l *subLog) Level() Level { + return Level(l.lvl.Load()) } // SetLevel changes the logging level to the passed level. // // This is part of the Logger interface implementation. -func (l *slog) SetLevel(level Level) { - atomic.StoreUint32((*uint32)(&l.lvl), uint32(level)) +func (l *subLog) SetLevel(level Level) { + l.lvl.Store(int32(level)) } // Disabled is a Logger that will never output anything. var Disabled Logger func init() { - Disabled = &slog{lvl: LevelOff, b: NewBackend(ioutil.Discard)} + Disabled = newSubLog("", NewBackend(io.Discard), LevelOff) } diff --git a/slog.go b/slog.go new file mode 100644 index 0000000..9e90a88 --- /dev/null +++ b/slog.go @@ -0,0 +1,223 @@ +package btclog + +import ( + "context" + "fmt" + "log/slog" +) + +// Handler wraps the slog.Handler interface with a few more methods that we +// need in order to satisfy the Logger interface. +type Handler interface { + slog.Handler + + // Level returns the current logging level of the Handler. + Level() Level + + // SetLevel changes the logging level of the Handler to the passed + // level. + SetLevel(level Level) + + // SubSystem returns a copy of the given handler but with the new tag. + SubSystem(tag string) Handler +} + +// sLogger is an implementation of Logger backed by a structured sLogger. +type sLogger struct { + Handler + logger *slog.Logger +} + +// NewSLogger constructs a new structured logger from the given Handler. +func NewSLogger(handler Handler) Logger { + return &sLogger{ + Handler: handler, + logger: slog.New(handler), + } +} + +// Tracef formats message according to format specifier, prepends the prefix as +// necessary, and writes to log with LevelTrace. +// +// This is part of the Logger interface implementation. +func (l *sLogger) Tracef(format string, params ...any) { + l.toSlogf(LevelTrace, format, params...) +} + +// Debugf formats message according to format specifier, prepends the prefix as +// necessary, and writes to log with LevelDebug. +// +// This is part of the Logger interface implementation. +func (l *sLogger) Debugf(format string, params ...any) { + l.toSlogf(LevelDebug, format, params...) +} + +// Infof formats message according to format specifier, prepends the prefix as +// necessary, and writes to log with LevelInfo. +// +// This is part of the Logger interface implementation. +func (l *sLogger) Infof(format string, params ...any) { + l.toSlogf(LevelInfo, format, params...) +} + +// Warnf formats message according to format specifier, prepends the prefix as +// necessary, and writes to log with LevelWarn. +// +// This is part of the Logger interface implementation. +func (l *sLogger) Warnf(format string, params ...any) { + l.toSlogf(LevelWarn, format, params...) +} + +// Errorf formats message according to format specifier, prepends the prefix as +// necessary, and writes to log with LevelError. +// +// This is part of the Logger interface implementation. +func (l *sLogger) Errorf(format string, params ...any) { + l.toSlogf(LevelError, format, params...) +} + +// Criticalf formats message according to format specifier, prepends the prefix as +// necessary, and writes to log with LevelCritical. +// +// This is part of the Logger interface implementation. +func (l *sLogger) Criticalf(format string, params ...any) { + l.toSlogf(LevelCritical, format, params...) +} + +// Trace formats message using the default formats for its operands, prepends +// the prefix as necessary, and writes to log with LevelTrace. +// +// This is part of the Logger interface implementation. +func (l *sLogger) Trace(v ...any) { + l.toSlog(LevelTrace, v...) +} + +// Debug formats message using the default formats for its operands, prepends +// the prefix as necessary, and writes to log with LevelDebug. +// +// This is part of the Logger interface implementation. +func (l *sLogger) Debug(v ...any) { + l.toSlog(LevelDebug, v...) +} + +// Info formats message using the default formats for its operands, prepends +// the prefix as necessary, and writes to log with LevelInfo. +// +// This is part of the Logger interface implementation. +func (l *sLogger) Info(v ...any) { + l.toSlog(LevelInfo, v...) +} + +// Warn formats message using the default formats for its operands, prepends +// the prefix as necessary, and writes to log with LevelWarn. +// +// This is part of the Logger interface implementation. +func (l *sLogger) Warn(v ...any) { + l.toSlog(LevelWarn, v...) +} + +// Error formats message using the default formats for its operands, prepends +// the prefix as necessary, and writes to log with LevelError. +// +// This is part of the Logger interface implementation. +func (l *sLogger) Error(v ...any) { + l.toSlog(LevelError, v...) +} + +// Critical formats message using the default formats for its operands, prepends +// the prefix as necessary, and writes to log with LevelCritical. +// +// This is part of the Logger interface implementation. +func (l *sLogger) Critical(v ...any) { + l.toSlog(LevelCritical, v...) +} + +// TraceS writes a structured log with the given message and key-value pair +// attributes with LevelTrace to the log. +// +// 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...) +} + +// DebugS writes a structured log with the given message and key-value pair +// attributes with LevelDebug to the log. +// +// 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...) +} + +// InfoS writes a structured log with the given message and key-value pair +// attributes with LevelInfo to the log. +// +// 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...) +} + +// WarnS writes a structured log with the given message and key-value pair +// attributes with LevelWarn to the log. +// +// This is part of the Logger interface implementation. +func (l *sLogger) WarnS(ctx context.Context, msg string, err error, + attrs ...any) { + + if err != nil { + attrs = append([]any{slog.String("err", err.Error())}, attrs...) + } + + l.toSlogS(ctx, LevelWarn, msg, attrs...) +} + +// ErrorS writes a structured log with the given message and key-value pair +// attributes with LevelError to the log. +// +// This is part of the Logger interface implementation. +func (l *sLogger) ErrorS(ctx context.Context, msg string, err error, + attrs ...any) { + + if err != nil { + attrs = append([]any{slog.String("err", err.Error())}, attrs...) + } + + l.toSlogS(ctx, LevelError, msg, attrs...) +} + +// CriticalS writes a structured log with the given message and key-value pair +// attributes with LevelCritical to the log. +// +// 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 Level, format string, params ...any) { + l.logger.Log(context.Background(), slog.Level(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 Level, v ...any) { + l.logger.Log(context.Background(), slog.Level(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 Level, msg string, + attrs ...any) { + + l.logger.Log(ctx, slog.Level(level), msg, mergeAttrs(ctx, attrs)...) +} + +var _ Logger = (*sLogger)(nil)