From c49e5da4a56284ced712aeaf9c25bb28c8aae68d Mon Sep 17 00:00:00 2001 From: Simon Richardson Date: Tue, 26 Sep 2023 11:00:08 +0100 Subject: [PATCH] Implement attributes to the loggo package In order to correctly interface with the log/slog package and to take advantage of structured logging, we now introduce attributes. Currently Info and Infof are different, in the fact that Info is the structured variation. It expects every argument to be a attribute after the initial message string. This then allows us to have a slog backend without migrating away from loggo directly. We have all the benefits of loggo plus we can take advantage of the new logging infra. --- attrs/attrs.go | 79 ++++++++++++++++++++++++++++++++++++++++++++ entry.go | 4 +++ example/first.go | 3 +- example/main.go | 31 +++++++++++++---- formatter.go | 47 ++++++++++++++++++++++++-- logger.go | 72 +++++++++++++++++++++++++++++++++++++++- loggocolor/writer.go | 25 ++++++++++++++ slog/writer.go | 54 ++++++++++++++++++++++++------ 8 files changed, 294 insertions(+), 21 deletions(-) create mode 100644 attrs/attrs.go diff --git a/attrs/attrs.go b/attrs/attrs.go new file mode 100644 index 0000000..b0d48b6 --- /dev/null +++ b/attrs/attrs.go @@ -0,0 +1,79 @@ +package attrs + +import ( + "fmt" + "time" +) + +type AttrValue[T any] interface { + Key() string + Value() T +} + +type attr[T any] struct { + key string + value T +} + +func (s attr[T]) Key() string { + return s.key +} + +func (s attr[T]) Value() T { + return s.value +} + +func String(k, v string) AttrValue[string] { + return attr[string]{key: k, value: v} +} + +func Int(k string, v int) AttrValue[int] { + return attr[int]{key: k, value: v} +} + +func Int64(k string, v int64) AttrValue[int64] { + return attr[int64]{key: k, value: v} +} + +func Uint64(k string, v uint64) AttrValue[uint64] { + return attr[uint64]{key: k, value: v} +} + +func Float64(k string, v float64) AttrValue[float64] { + return attr[float64]{key: k, value: v} +} + +func Bool(k string, v bool) AttrValue[bool] { + return attr[bool]{key: k, value: v} +} + +func Time(k string, v time.Time) AttrValue[time.Time] { + return attr[time.Time]{key: k, value: v} +} + +func Duration(k string, v time.Duration) AttrValue[time.Duration] { + return attr[time.Duration]{key: k, value: v} +} + +func Any(k string, v any) AttrValue[any] { + return attr[any]{key: k, value: v} +} + +func Valid(attrs []any) error { + for _, attr := range attrs { + switch a := attr.(type) { + case AttrValue[string]: + case AttrValue[int]: + case AttrValue[int64]: + case AttrValue[uint64]: + case AttrValue[float64]: + case AttrValue[bool]: + case AttrValue[time.Time]: + case AttrValue[time.Duration]: + case AttrValue[any]: + default: + return fmt.Errorf("invalid attribute type %T", a) + } + } + return nil +} diff --git a/entry.go b/entry.go index 29a7fd6..aa08b9c 100644 --- a/entry.go +++ b/entry.go @@ -21,4 +21,8 @@ type Entry struct { Message string // Labels is the label associated with the log message. Labels []string + // PC is the program counter of the log call. + PC uintptr + // Attrs is the list of attributes associated with the log message. + Attrs []any } diff --git a/example/first.go b/example/first.go index 9e88551..b2fab0c 100644 --- a/example/first.go +++ b/example/first.go @@ -2,12 +2,13 @@ package main import ( "github.com/juju/loggo" + "github.com/juju/loggo/attrs" ) var first = loggo.GetLogger("first") func FirstCritical(message string) { - first.Criticalf(message) + first.Critical(message, attrs.String("baz", "boo")) } func FirstError(message string) { diff --git a/example/main.go b/example/main.go index c10526d..03b871e 100644 --- a/example/main.go +++ b/example/main.go @@ -3,28 +3,48 @@ package main import ( "fmt" "log" + "log/slog" "os" "github.com/juju/loggo" + "github.com/juju/loggo/attrs" + loggoslog "github.com/juju/loggo/slog" ) var rootLogger = loggo.GetLogger("") func main() { args := os.Args - if len(args) > 1 { + if len(args) <= 1 { + fmt.Println("Add a parameter to configure the logging:") + fmt.Println(`E.g. "=INFO;first=TRACE" or "=INFO;first=TRACE" "slog"`) + } + num := len(args) + if num > 1 { if err := loggo.ConfigureLoggers(args[1]); err != nil { log.Fatal(err) } - } else { - fmt.Println("Add a parameter to configure the logging:") - fmt.Println("E.g. \"=INFO;first=TRACE\"") } + fmt.Println("\nCurrent logging levels:") fmt.Println(loggo.LoggerInfo()) + + if num > 2 { + if args[2] == "slog" { + handler := slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{ + Level: loggoslog.DefaultLevel(loggo.DefaultContext().Config()), + }) + loggo.ReplaceDefaultWriter(loggoslog.NewSlogWriter(handler)) + + fmt.Println("Using log/slog writer:") + } else { + log.Fatalf("unknown logging type %q", args[2]) + } + } + fmt.Println("") - rootLogger.Infof("Start of test.") + rootLogger.Info("Start of test.", attrs.String("foo", "bar")) FirstCritical("first critical") FirstError("first error") @@ -39,5 +59,4 @@ func main() { SecondInfo("second info") SecondDebug("second debug") SecondTrace("second trace") - } diff --git a/formatter.go b/formatter.go index 3acc7e7..98048f3 100644 --- a/formatter.go +++ b/formatter.go @@ -8,17 +8,60 @@ import ( "os" "path/filepath" "time" + + "github.com/juju/loggo/attrs" ) // DefaultFormatter returns the parameters separated by spaces except for // filename and line which are separated by a colon. The timestamp is shown // to second resolution in UTC. For example: -// 2016-07-02 15:04:05 +// +// 2016-07-02 15:04:05 func DefaultFormatter(entry Entry) string { ts := entry.Timestamp.In(time.UTC).Format("2006-01-02 15:04:05") // Just get the basename from the filename filename := filepath.Base(entry.Filename) - return fmt.Sprintf("%s %s %s %s:%d %s", ts, entry.Level, entry.Module, filename, entry.Line, entry.Message) + + var ( + format string + values []any + ) + for _, attr := range entry.Attrs { + switch a := attr.(type) { + case attrs.AttrValue[string]: + format += " %s=%s" + values = append(values, a.Key(), a.Value()) + case attrs.AttrValue[int]: + format += " %s=%d" + values = append(values, a.Key(), a.Value()) + case attrs.AttrValue[int64]: + format += " %s=%d" + values = append(values, a.Key(), a.Value()) + case attrs.AttrValue[uint64]: + format += " %s=%d" + values = append(values, a.Key(), a.Value()) + case attrs.AttrValue[float64]: + format += " %s=%f" + values = append(values, a.Key(), a.Value()) + case attrs.AttrValue[bool]: + format += " %s=%t" + values = append(values, a.Key(), a.Value()) + case attrs.AttrValue[time.Time]: + format += " %s=%v" + values = append(values, a.Key(), a.Value()) + case attrs.AttrValue[time.Duration]: + format += " %s=%v" + values = append(values, a.Key(), a.Value()) + case attrs.AttrValue[any]: + format += " %s=%v" + values = append(values, a.Key(), a.Value()) + } + } + + args := []any{ts, entry.Level, entry.Module, filename, entry.Line, entry.Message} + args = append(args, values...) + + return fmt.Sprintf("%s %s %s %s:%d %s"+format, args...) } // TimeFormat is the time format used for the default writer. diff --git a/logger.go b/logger.go index 4826aab..099c8c1 100644 --- a/logger.go +++ b/logger.go @@ -7,6 +7,8 @@ import ( "fmt" "runtime" "time" + + "github.com/juju/loggo/attrs" ) // A Logger represents a logging module. It has an associated logging @@ -127,7 +129,7 @@ func (logger Logger) LogCallf(calldepth int, level Level, message string, args . now := time.Now() // get this early. // Param to Caller is the call depth. Since this method is called from // the Logger methods, we want the place that those were called from. - _, file, line, ok := runtime.Caller(calldepth + 1) + pc, file, line, ok := runtime.Caller(calldepth + 1) if !ok { file = "???" line = 0 @@ -154,6 +156,7 @@ func (logger Logger) LogCallf(calldepth int, level Level, message string, args . Timestamp: now, Message: formattedMessage, Labels: module.labels, + PC: pc, }) } @@ -222,3 +225,70 @@ func (logger Logger) IsDebugEnabled() bool { func (logger Logger) IsTraceEnabled() bool { return logger.IsLevelEnabled(TRACE) } + +// Trace logs the message at trace level. +func (logger Logger) Trace(message string, attrs ...any) error { + return logger.LogCall(1, TRACE, message, attrs...) +} + +// Debug logs the message at debug level. +func (logger Logger) Debug(message string, attrs ...any) error { + return logger.LogCall(1, DEBUG, message, attrs...) +} + +// Info logs the message at info level. +func (logger Logger) Info(message string, attrs ...any) error { + return logger.LogCall(1, INFO, message, attrs...) +} + +// Error logs the message at error level. +func (logger Logger) Error(message string, attrs ...any) error { + return logger.LogCall(1, ERROR, message, attrs...) +} + +// Warning logs the message at warning level. +func (logger Logger) Warning(message string, attrs ...any) error { + return logger.LogCall(1, WARNING, message, attrs...) +} + +// Critical logs the message at critical level. +func (logger Logger) Critical(message string, attrs ...any) error { + return logger.LogCall(1, CRITICAL, message, attrs...) +} + +func (logger Logger) LogCall(calldepth int, level Level, message string, attributes ...any) error { + if err := attrs.Valid(attributes); err != nil { + return err + } + + module := logger.getModule() + if !module.willWrite(level) { + return nil + } + // Gather time, and filename, line number. + now := time.Now() // get this early. + // Param to Caller is the call depth. Since this method is called from + // the Logger methods, we want the place that those were called from. + pc, file, line, ok := runtime.Caller(calldepth + 1) + if !ok { + file = "???" + line = 0 + } + // Trim newline off format string, following usual + // Go logging conventions. + if len(message) > 0 && message[len(message)-1] == '\n' { + message = message[0 : len(message)-1] + } + + module.write(Entry{ + Level: level, + Filename: file, + Line: line, + Timestamp: now, + Message: message, + Labels: module.labels, + PC: pc, + Attrs: attributes, + }) + return nil +} diff --git a/loggocolor/writer.go b/loggocolor/writer.go index 86eafd0..b212f90 100644 --- a/loggocolor/writer.go +++ b/loggocolor/writer.go @@ -4,9 +4,11 @@ import ( "fmt" "io" "path/filepath" + "time" "github.com/juju/ansiterm" "github.com/juju/loggo" + "github.com/juju/loggo/attrs" ) var ( @@ -55,4 +57,27 @@ func (w *colorWriter) Write(entry loggo.Entry) { fmt.Fprintf(w.writer, " %s ", entry.Module) LocationColor.Fprintf(w.writer, "%s:%d ", filename, entry.Line) fmt.Fprintln(w.writer, entry.Message) + + for _, attr := range entry.Attrs { + switch a := attr.(type) { + case attrs.AttrValue[string]: + fmt.Fprintf(w.writer, " %s=%s\n", a.Key(), a.Value()) + case attrs.AttrValue[int]: + fmt.Fprintf(w.writer, " %s=%d\n", a.Key(), a.Value()) + case attrs.AttrValue[int64]: + fmt.Fprintf(w.writer, " %s=%d\n", a.Key(), a.Value()) + case attrs.AttrValue[uint64]: + fmt.Fprintf(w.writer, " %s=%d\n", a.Key(), a.Value()) + case attrs.AttrValue[float64]: + fmt.Fprintf(w.writer, " %s=%f\n", a.Key(), a.Value()) + case attrs.AttrValue[bool]: + fmt.Fprintf(w.writer, " %s=%t\n", a.Key(), a.Value()) + case attrs.AttrValue[time.Time]: + fmt.Fprintf(w.writer, " %s=%v\n", a.Key(), a.Value()) + case attrs.AttrValue[time.Duration]: + fmt.Fprintf(w.writer, " %s=%v\n", a.Key(), a.Value()) + case attrs.AttrValue[any]: + fmt.Fprintf(w.writer, " %s=%v\n", a.Key(), a.Value()) + } + } } diff --git a/slog/writer.go b/slog/writer.go index 974f224..48fddb6 100644 --- a/slog/writer.go +++ b/slog/writer.go @@ -4,29 +4,28 @@ import ( "context" "log/slog" "strings" + "time" "github.com/juju/loggo" + "github.com/juju/loggo/attrs" ) type slogWriter struct { writer slog.Handler } -// NewSlowWriter will write out slog severity levels. -func NewSlowWriter(writer slog.Handler) loggo.Writer { - return &slogWriter{writer} +// NewSlogWriter will write out slog severity levels. +func NewSlogWriter(writer slog.Handler) loggo.Writer { + return &slogWriter{writer: writer} } // Write implements Writer. func (w *slogWriter) Write(entry loggo.Entry) { record := slog.NewRecord( entry.Timestamp, - level(entry.Level), + Level(entry.Level), entry.Message, - // TODO (stickupkid): Add a way to log the caller ptr in the - // loggo.Entry. That way we can push the information directly into - // the slog.Record. - 0, + entry.PC, ) record.AddAttrs( @@ -37,17 +36,39 @@ func (w *slogWriter) Write(entry loggo.Entry) { if len(entry.Labels) > 0 { record.AddAttrs(slog.String("labels", strings.Join(entry.Labels, ","))) } + for _, attr := range entry.Attrs { + switch a := attr.(type) { + case attrs.AttrValue[string]: + record.AddAttrs(slog.String(a.Key(), a.Value())) + case attrs.AttrValue[int]: + record.AddAttrs(slog.Int(a.Key(), a.Value())) + case attrs.AttrValue[int64]: + record.AddAttrs(slog.Int64(a.Key(), a.Value())) + case attrs.AttrValue[uint64]: + record.AddAttrs(slog.Uint64(a.Key(), a.Value())) + case attrs.AttrValue[float64]: + record.AddAttrs(slog.Float64(a.Key(), a.Value())) + case attrs.AttrValue[bool]: + record.AddAttrs(slog.Bool(a.Key(), a.Value())) + case attrs.AttrValue[time.Time]: + record.AddAttrs(slog.Time(a.Key(), a.Value())) + case attrs.AttrValue[time.Duration]: + record.AddAttrs(slog.Duration(a.Key(), a.Value())) + case attrs.AttrValue[any]: + record.AddAttrs(slog.Any(a.Key(), a.Value())) + } + } w.writer.Handle(context.Background(), record) } -// The level function allows levels to be mapped to slog levels. Although, +// Level function allows levels to be mapped to slog levels. Although, // slog doesn't explicitly implement all the levels that we require for mapping // it does allow for custom levels to be added. This is done by using the // slog.Level type as an int64. // Reading the documentation https://pkg.go.dev/log/slog#Level explains how // to insert custom levels. -func level(level loggo.Level) slog.Level { +func Level(level loggo.Level) slog.Level { switch level { case loggo.TRACE: return slog.LevelDebug - 1 @@ -56,7 +77,7 @@ func level(level loggo.Level) slog.Level { case loggo.INFO: return slog.LevelInfo case loggo.WARNING: - return slog.LevelInfo + 1 + return slog.LevelWarn case loggo.ERROR: return slog.LevelError case loggo.CRITICAL: @@ -65,3 +86,14 @@ func level(level loggo.Level) slog.Level { panic("unknown level") } } + +// DefaultLevel returns the lowest level from the loggo config. +func DefaultLevel(v loggo.Config) slog.Level { + lowest := loggo.CRITICAL + for _, level := range v { + if level < lowest { + lowest = level + } + } + return Level(lowest) +}