From be73ae67e0c419dabc09c895c6d23e48bbf392e2 Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Wed, 18 Sep 2024 11:32:37 +0200 Subject: [PATCH 01/11] go.mod: create go module --- go.mod | 3 +++ 1 file changed, 3 insertions(+) create mode 100644 go.mod 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 From e1e32faf59422405bf51ca958099a1f5d4daeaec Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Mon, 16 Sep 2024 11:17:09 +0200 Subject: [PATCH 02/11] cosmetic: replace interface{} with any --- interface.go | 24 ++++++++++++------------ log.go | 30 +++++++++++++++--------------- 2 files changed, 27 insertions(+), 27 deletions(-) diff --git a/interface.go b/interface.go index 64f74fc..06153f7 100644 --- a/interface.go +++ b/interface.go @@ -10,51 +10,51 @@ package btclog 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) // Level returns the current logging level. Level() Level diff --git a/log.go b/log.go index d8f3dcd..56871b7 100644 --- a/log.go +++ b/log.go @@ -158,7 +158,7 @@ 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{} { + New: func() any { b := make([]byte, 0, 120) return &b // pointer to slice to avoid boxing alloc }, @@ -262,7 +262,7 @@ 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() @@ -289,7 +289,7 @@ func (b *Backend) print(lvl, tag string, args ...interface{}) { // 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() @@ -330,7 +330,7 @@ type slog struct { // 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 *slog) Trace(args ...any) { lvl := l.Level() if lvl <= LevelTrace { l.b.print("TRC", l.tag, args...) @@ -341,7 +341,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 *slog) Tracef(format string, args ...any) { lvl := l.Level() if lvl <= LevelTrace { l.b.printf("TRC", l.tag, format, args...) @@ -352,7 +352,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 *slog) Debug(args ...any) { lvl := l.Level() if lvl <= LevelDebug { l.b.print("DBG", l.tag, args...) @@ -363,7 +363,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 *slog) Debugf(format string, args ...any) { lvl := l.Level() if lvl <= LevelDebug { l.b.printf("DBG", l.tag, format, args...) @@ -374,7 +374,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 *slog) Info(args ...any) { lvl := l.Level() if lvl <= LevelInfo { l.b.print("INF", l.tag, args...) @@ -385,7 +385,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 *slog) Infof(format string, args ...any) { lvl := l.Level() if lvl <= LevelInfo { l.b.printf("INF", l.tag, format, args...) @@ -396,7 +396,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 *slog) Warn(args ...any) { lvl := l.Level() if lvl <= LevelWarn { l.b.print("WRN", l.tag, args...) @@ -407,7 +407,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 *slog) Warnf(format string, args ...any) { lvl := l.Level() if lvl <= LevelWarn { l.b.printf("WRN", l.tag, format, args...) @@ -418,7 +418,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 *slog) Error(args ...any) { lvl := l.Level() if lvl <= LevelError { l.b.print("ERR", l.tag, args...) @@ -429,7 +429,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 *slog) Errorf(format string, args ...any) { lvl := l.Level() if lvl <= LevelError { l.b.printf("ERR", l.tag, format, args...) @@ -440,7 +440,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 *slog) Critical(args ...any) { lvl := l.Level() if lvl <= LevelCritical { l.b.print("CRT", l.tag, args...) @@ -451,7 +451,7 @@ 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 *slog) Criticalf(format string, args ...any) { lvl := l.Level() if lvl <= LevelCritical { l.b.printf("CRT", l.tag, format, args...) From 2aa51f8f062858c56c5b6709b6db6a9511c2e819 Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Tue, 10 Sep 2024 15:28:36 +0200 Subject: [PATCH 03/11] log: rename slog to subLog So that it does not clash with the standard lib's slog package. --- log.go | 36 ++++++++++++++++++------------------ 1 file changed, 18 insertions(+), 18 deletions(-) diff --git a/log.go b/log.go index 56871b7..00f4ff5 100644 --- a/log.go +++ b/log.go @@ -316,11 +316,11 @@ func (b *Backend) printf(lvl, tag string, format string, args ...any) { // 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 &subLog{LevelInfo, subsystemTag, b} } -// slog is a subsystem logger for a Backend. Implements the Logger interface. -type slog struct { +// subLog is a subsystem logger for a Backend. Implements the Logger interface. +type subLog struct { lvl Level // atomic tag string b *Backend @@ -330,7 +330,7 @@ type slog struct { // the prefix as necessary, and writes to log with LevelTrace. // // This is part of the Logger interface implementation. -func (l *slog) Trace(args ...any) { +func (l *subLog) Trace(args ...any) { lvl := l.Level() if lvl <= LevelTrace { l.b.print("TRC", l.tag, args...) @@ -341,7 +341,7 @@ func (l *slog) Trace(args ...any) { // necessary, and writes to log with LevelTrace. // // This is part of the Logger interface implementation. -func (l *slog) Tracef(format string, args ...any) { +func (l *subLog) Tracef(format string, args ...any) { lvl := l.Level() if lvl <= LevelTrace { l.b.printf("TRC", l.tag, format, args...) @@ -352,7 +352,7 @@ func (l *slog) Tracef(format string, args ...any) { // the prefix as necessary, and writes to log with LevelDebug. // // This is part of the Logger interface implementation. -func (l *slog) Debug(args ...any) { +func (l *subLog) Debug(args ...any) { lvl := l.Level() if lvl <= LevelDebug { l.b.print("DBG", l.tag, args...) @@ -363,7 +363,7 @@ func (l *slog) Debug(args ...any) { // necessary, and writes to log with LevelDebug. // // This is part of the Logger interface implementation. -func (l *slog) Debugf(format string, args ...any) { +func (l *subLog) Debugf(format string, args ...any) { lvl := l.Level() if lvl <= LevelDebug { l.b.printf("DBG", l.tag, format, args...) @@ -374,7 +374,7 @@ func (l *slog) Debugf(format string, args ...any) { // the prefix as necessary, and writes to log with LevelInfo. // // This is part of the Logger interface implementation. -func (l *slog) Info(args ...any) { +func (l *subLog) Info(args ...any) { lvl := l.Level() if lvl <= LevelInfo { l.b.print("INF", l.tag, args...) @@ -385,7 +385,7 @@ func (l *slog) Info(args ...any) { // necessary, and writes to log with LevelInfo. // // This is part of the Logger interface implementation. -func (l *slog) Infof(format string, args ...any) { +func (l *subLog) Infof(format string, args ...any) { lvl := l.Level() if lvl <= LevelInfo { l.b.printf("INF", l.tag, format, args...) @@ -396,7 +396,7 @@ func (l *slog) Infof(format string, args ...any) { // the prefix as necessary, and writes to log with LevelWarn. // // This is part of the Logger interface implementation. -func (l *slog) Warn(args ...any) { +func (l *subLog) Warn(args ...any) { lvl := l.Level() if lvl <= LevelWarn { l.b.print("WRN", l.tag, args...) @@ -407,7 +407,7 @@ func (l *slog) Warn(args ...any) { // necessary, and writes to log with LevelWarn. // // This is part of the Logger interface implementation. -func (l *slog) Warnf(format string, args ...any) { +func (l *subLog) Warnf(format string, args ...any) { lvl := l.Level() if lvl <= LevelWarn { l.b.printf("WRN", l.tag, format, args...) @@ -418,7 +418,7 @@ func (l *slog) Warnf(format string, args ...any) { // the prefix as necessary, and writes to log with LevelError. // // This is part of the Logger interface implementation. -func (l *slog) Error(args ...any) { +func (l *subLog) Error(args ...any) { lvl := l.Level() if lvl <= LevelError { l.b.print("ERR", l.tag, args...) @@ -429,7 +429,7 @@ func (l *slog) Error(args ...any) { // necessary, and writes to log with LevelError. // // This is part of the Logger interface implementation. -func (l *slog) Errorf(format string, args ...any) { +func (l *subLog) Errorf(format string, args ...any) { lvl := l.Level() if lvl <= LevelError { l.b.printf("ERR", l.tag, format, args...) @@ -440,7 +440,7 @@ func (l *slog) Errorf(format string, args ...any) { // the prefix as necessary, and writes to log with LevelCritical. // // This is part of the Logger interface implementation. -func (l *slog) Critical(args ...any) { +func (l *subLog) Critical(args ...any) { lvl := l.Level() if lvl <= LevelCritical { l.b.print("CRT", l.tag, args...) @@ -451,7 +451,7 @@ func (l *slog) Critical(args ...any) { // as necessary, and writes to log with LevelCritical. // // This is part of the Logger interface implementation. -func (l *slog) Criticalf(format string, args ...any) { +func (l *subLog) Criticalf(format string, args ...any) { lvl := l.Level() if lvl <= LevelCritical { l.b.printf("CRT", l.tag, format, args...) @@ -461,14 +461,14 @@ func (l *slog) Criticalf(format string, args ...any) { // Level returns the current logging level // // This is part of the Logger interface implementation. -func (l *slog) Level() Level { +func (l *subLog) Level() Level { return Level(atomic.LoadUint32((*uint32)(&l.lvl))) } // SetLevel changes the logging level to the passed level. // // This is part of the Logger interface implementation. -func (l *slog) SetLevel(level Level) { +func (l *subLog) SetLevel(level Level) { atomic.StoreUint32((*uint32)(&l.lvl), uint32(level)) } @@ -476,5 +476,5 @@ func (l *slog) SetLevel(level Level) { var Disabled Logger func init() { - Disabled = &slog{lvl: LevelOff, b: NewBackend(ioutil.Discard)} + Disabled = &subLog{lvl: LevelOff, b: NewBackend(ioutil.Discard)} } From 6d470d51c01056aefe3c2890acf196683109d372 Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Tue, 10 Sep 2024 15:38:12 +0200 Subject: [PATCH 04/11] level+log: update levels to use slog levels Reuse some of the slog.Level types and add a few of our own. Also, move level logic to its own file for readability. --- level.go | 82 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++ log.go | 73 +++++++++++-------------------------------------- 2 files changed, 98 insertions(+), 57 deletions(-) create mode 100644 level.go diff --git a/level.go b/level.go new file mode 100644 index 0000000..db84295 --- /dev/null +++ b/level.go @@ -0,0 +1,82 @@ +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) + } +} diff --git a/log.go b/log.go index 00f4ff5..8e4b6ee 100644 --- a/log.go +++ b/log.go @@ -36,7 +36,6 @@ import ( "bytes" "fmt" "io" - "io/ioutil" "os" "runtime" "strings" @@ -74,57 +73,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} @@ -316,16 +264,27 @@ func (b *Backend) printf(lvl, tag string, format string, args ...any) { // 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 &subLog{LevelInfo, subsystemTag, b} + return newSubLog(subsystemTag, b, LevelInfo) } // subLog is a subsystem logger for a Backend. Implements the Logger interface. type subLog struct { - lvl Level // atomic + 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. // @@ -462,19 +421,19 @@ func (l *subLog) Criticalf(format string, args ...any) { // // This is part of the Logger interface implementation. func (l *subLog) Level() Level { - return Level(atomic.LoadUint32((*uint32)(&l.lvl))) + return Level(l.lvl.Load()) } // SetLevel changes the logging level to the passed level. // // This is part of the Logger interface implementation. func (l *subLog) SetLevel(level Level) { - atomic.StoreUint32((*uint32)(&l.lvl), uint32(level)) + l.lvl.Store(int32(level)) } // Disabled is a Logger that will never output anything. var Disabled Logger func init() { - Disabled = &subLog{lvl: LevelOff, b: NewBackend(ioutil.Discard)} + Disabled = newSubLog("", NewBackend(io.Discard), LevelOff) } From e2395325b312968fc7ca205d2aeb03413db2d3ee Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Tue, 10 Sep 2024 15:47:54 +0200 Subject: [PATCH 05/11] interface+log: add new structured log methods And let subLog implement the methods by calling its existing methods. Note that subLog will not produce structured logs as of this commit. In future, it can be updated to use an slog.Logger and this package can implement a default slog.Handler. --- interface.go | 26 +++++++++++++++++++++++ log.go | 59 ++++++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 85 insertions(+) diff --git a/interface.go b/interface.go index 06153f7..2a18a57 100644 --- a/interface.go +++ b/interface.go @@ -4,6 +4,8 @@ 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. @@ -56,6 +58,30 @@ type Logger interface { // and writes to log with LevelCritical. 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/log.go b/log.go index 8e4b6ee..8b5bbbc 100644 --- a/log.go +++ b/log.go @@ -34,8 +34,10 @@ package btclog import ( "bytes" + "context" "fmt" "io" + "log/slog" "os" "runtime" "strings" @@ -417,6 +419,63 @@ func (l *subLog) Criticalf(format string, args ...any) { } } +// 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. From 5d3645068702b5aea2dc28418a4a5ff6e49002b9 Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Tue, 10 Sep 2024 16:14:45 +0200 Subject: [PATCH 06/11] slog: add an slog backed implementation of Logger --- attrs.go | 36 +++++++++ slog.go | 223 +++++++++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 259 insertions(+) create mode 100644 attrs.go create mode 100644 slog.go 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/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) From 73f4f3a05a3281700fd14fb16b3ec3ea18b4ce97 Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Tue, 17 Sep 2024 18:36:02 +0200 Subject: [PATCH 07/11] buffer+log: revamp the buffer pool Update the buffer pool to use a concrete type and steel some other updates from the buffer pool used by std lib. Also adds a few useful helpers that we will use later on and also factors out the timestamp writing part from formatHeader since we will use that again later. --- buffer.go | 51 ++++++++++++++++++++++++++++++++++++ log.go | 78 ++++++++++++++++++++++--------------------------------- 2 files changed, 82 insertions(+), 47 deletions(-) create mode 100644 buffer.go 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/log.go b/log.go index 8b5bbbc..444c350 100644 --- a/log.go +++ b/log.go @@ -105,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() any { - 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 @@ -145,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, "] "...) @@ -182,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 @@ -215,7 +199,7 @@ func callsite(flag uint32) (string, int) { 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 @@ -232,7 +216,7 @@ func (b *Backend) print(lvl, tag string, args ...any) { b.w.Write(*bytebuf) b.mu.Unlock() - recycleBuffer(bytebuf) + bytebuf.free() } // printf outputs a log message to the writer associated with the backend after @@ -242,7 +226,7 @@ func (b *Backend) print(lvl, tag string, args ...any) { 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 @@ -259,7 +243,7 @@ func (b *Backend) printf(lvl, tag string, format string, args ...any) { b.w.Write(*bytebuf) b.mu.Unlock() - recycleBuffer(bytebuf) + bytebuf.free() } // Logger returns a new logger for a particular subsystem that writes to the From 403cd25e0d289886a552d943c0a0329506e163e8 Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Tue, 17 Sep 2024 18:39:06 +0200 Subject: [PATCH 08/11] log: refactor callsite Since we will use it later no with a different skip depth. --- log.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/log.go b/log.go index 444c350..b9bd1c7 100644 --- a/log.go +++ b/log.go @@ -174,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 } @@ -204,7 +204,7 @@ func (b *Backend) print(lvl, tag string, args ...any) { 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) @@ -231,7 +231,7 @@ func (b *Backend) printf(lvl, tag string, format string, args ...any) { 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) From 13b1a59b8f0395bc04e32ed79ba85afd0db77829 Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Tue, 17 Sep 2024 18:55:24 +0200 Subject: [PATCH 09/11] handler: add a DefaultHandler Handler implementation Which is a valid Handler that can be used with the NewSloggger call. --- handler.go | 434 ++++++++++++++++++++++++++++++++++++++++++++++++ handler_test.go | 155 +++++++++++++++++ 2 files changed, 589 insertions(+) create mode 100644 handler.go create mode 100644 handler_test.go diff --git a/handler.go b/handler.go new file mode 100644 index 0000000..244de6c --- /dev/null +++ b/handler.go @@ -0,0 +1,434 @@ +package btclog + +import ( + "context" + "fmt" + "io" + "log/slog" + "strconv" + "sync" + "sync/atomic" + "time" + "unicode" + "unicode/utf8" +) + +// 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 + } +} + +// 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) 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(str) +} + +func (d *DefaultHandler) writeCallSite(buf *buffer, file string, line int) { + if file == "" { + return + } + + buf.writeString(fmt.Sprintf(" %s:%d", file, line)) +} + +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(key) +} + +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()) + } + }) + } +} From 4e45b38ef5a17b8a38e7e55682fa385a74e6bbd3 Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Tue, 17 Sep 2024 18:58:59 +0200 Subject: [PATCH 10/11] handler: add styled output option --- handler.go | 46 +++++++++++++++++++++++++++++++++++++++++++--- level.go | 28 ++++++++++++++++++++++++++++ 2 files changed, 71 insertions(+), 3 deletions(-) diff --git a/handler.go b/handler.go index 244de6c..aa64523 100644 --- a/handler.go +++ b/handler.go @@ -6,6 +6,7 @@ import ( "io" "log/slog" "strconv" + "strings" "sync" "sync/atomic" "time" @@ -13,6 +14,15 @@ import ( "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) @@ -49,6 +59,15 @@ func WithCallerFlags(flags uint32) HandlerOption { } } +// 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 { @@ -228,6 +247,23 @@ func (d *DefaultHandler) with(tag string, withCallstackOffset bool, 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() @@ -244,7 +280,9 @@ func (d *DefaultHandler) appendAttr(buf *buffer, a slog.Attr) { func (d *DefaultHandler) writeLevel(buf *buffer, level Level) { str := fmt.Sprintf("[%s]", level) - buf.writeString(str) + buf.writeString(d.styleString( + str, boldSeq, string(level.ansiColoSeq())), + ) } func (d *DefaultHandler) writeCallSite(buf *buffer, file string, line int) { @@ -252,7 +290,9 @@ func (d *DefaultHandler) writeCallSite(buf *buffer, file string, line int) { return } - buf.writeString(fmt.Sprintf(" %s:%d", file, line)) + buf.writeString( + d.styleString(fmt.Sprintf(" %s:%d", file, line), faintSeq), + ) } func appendString(buf *buffer, str string) { @@ -270,7 +310,7 @@ func (d *DefaultHandler) appendKey(buf *buffer, key string) { } key += "=" - buf.writeString(key) + buf.writeString(d.styleString(key, faintSeq)) } func appendValue(buf *buffer, v slog.Value) { diff --git a/level.go b/level.go index db84295..b840ebb 100644 --- a/level.go +++ b/level.go @@ -80,3 +80,31 @@ func (l Level) String() string { 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 + } +} From 8b0f4456bdbb21fe4600f3cf507504199cf3ea5b Mon Sep 17 00:00:00 2001 From: Elle Mouton Date: Mon, 23 Sep 2024 13:29:41 +0900 Subject: [PATCH 11/11] travis: remove travis yml --- .travis.yml | 13 ------------- 1 file changed, 13 deletions(-) delete mode 100644 .travis.yml 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