From c79174f8e51e886697e4b9a24a1522f690b2aab4 Mon Sep 17 00:00:00 2001 From: Toastie <toastie@toastiet0ast.com> Date: Sat, 22 Mar 2025 19:34:13 +1300 Subject: [PATCH] tint v1.0.0 --- .gitignore | 1 + buffer.go | 46 ++++ go.mod | 3 + handler.go | 534 ++++++++++++++++++++++++++++++++++++++++++++ handler_test.go | 581 ++++++++++++++++++++++++++++++++++++++++++++++++ 5 files changed, 1165 insertions(+) create mode 100644 .gitignore create mode 100644 buffer.go create mode 100644 go.mod create mode 100644 handler.go create mode 100644 handler_test.go diff --git a/.gitignore b/.gitignore new file mode 100644 index 0000000..85e7c1d --- /dev/null +++ b/.gitignore @@ -0,0 +1 @@ +/.idea/ diff --git a/buffer.go b/buffer.go new file mode 100644 index 0000000..4d7321a --- /dev/null +++ b/buffer.go @@ -0,0 +1,46 @@ +package tint + +import "sync" + +type buffer []byte + +var bufPool = sync.Pool{ + New: func() any { + b := make(buffer, 0, 1024) + return (*buffer)(&b) + }, +} + +func newBuffer() *buffer { + return bufPool.Get().(*buffer) +} + +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] + bufPool.Put(b) + } +} +func (b *buffer) Write(bytes []byte) (int, error) { + *b = append(*b, bytes...) + return len(bytes), nil +} + +func (b *buffer) WriteByte(char byte) error { + *b = append(*b, char) + return nil +} + +func (b *buffer) WriteString(str string) (int, error) { + *b = append(*b, str...) + return len(str), nil +} + +func (b *buffer) WriteStringIf(ok bool, str string) (int, error) { + if !ok { + return 0, nil + } + return b.WriteString(str) +} diff --git a/go.mod b/go.mod new file mode 100644 index 0000000..6b08636 --- /dev/null +++ b/go.mod @@ -0,0 +1,3 @@ +module toastielab.dev/toastie-stuff/tint + +go 1.22 diff --git a/handler.go b/handler.go new file mode 100644 index 0000000..6bb8536 --- /dev/null +++ b/handler.go @@ -0,0 +1,534 @@ +/* +Package tint implements a zero-dependency [slog.Handler] that writes tinted +(colorized) logs. The output format is inspired by the [zerolog.ConsoleWriter] +and [slog.TextHandler]. + +The output format can be customized using [Options], which is a drop-in +replacement for [slog.HandlerOptions]. + +# Customizing Colors + +Colors can be customized using the `Options.LevelColors` and `Options.Colors` attributes. +See [tint.Options] for details. + + // ANSI escape codes: https://en.wikipedia.org/wiki/ANSI_escape_code + const ( + ansiFaint = "\033[2m" + ansiBrightRed = "\033[91m" + ansiBrightRedFaint = "\033[91;2m" + ansiBrightGreen = "\033[92m" + ansiBrightYellow = "\033[93m" + ansiBrightYellowBold = "\033[93;1m" + ansiBrightBlueBold = "\033[94;1m" + ansiBrightMagenta = "\033[95m" + ) + + // create a new logger with custom colors + w := os.Stderr + logger := slog.New( + tint.NewHandler(w, &tint.Options{ + LevelColors: map[slog.Level]string{ + slog.LevelDebug: ansiBrightMagenta, + slog.LevelInfo: ansiBrightGreen, + slog.LevelWarn: ansiBrightYellow, + slog.LevelError: ansiBrightRed, + }, + Colors: map[tint.Kind]string{ + tint.KindTime: ansiBrightYellowBold, + tint.KindSourceFile: ansiFaint, + tint.KindSourceSeparator: ansiFaint, + tint.KindSourceLine: ansiFaint, + tint.KindMessage: ansiBrightBlueBold, + tint.KindKey: ansiFaint, + tint.KindSeparator: ansiFaint, + tint.KindValue: ansiBrightBlueBold, + tint.KindErrorKey: ansiBrightRedFaint, + tint.KindErrorSeparator: ansiBrightRedFaint, + tint.KindErrorValue: ansiBrightRed, + }, + }), + ) + +# Customize Attributes + +Options.ReplaceAttr can be used to alter or drop attributes. If set, it is +called on each non-group attribute before it is logged. +See [slog.HandlerOptions] for details. + + w := os.Stderr + logger := slog.New( + tint.NewHandler(w, &tint.Options{ + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + if a.Key == slog.TimeKey && len(groups) == 0 { + return slog.Attr{} + } + return a + }, + }), + ) + +# Automatically Enable Colors + +Colors are enabled by default and can be disabled using the Options.NoColor +attribute. To automatically enable colors based on the terminal capabilities, +use e.g. the [go-isatty] package. + + w := os.Stderr + logger := slog.New( + tint.NewHandler(w, &tint.Options{ + NoColor: !isatty.IsTerminal(w.Fd()), + }), + ) + +# Windows Support + +Color support on Windows can be added by using e.g. the [go-colorable] package. + + w := os.Stderr + logger := slog.New( + tint.NewHandler(colorable.NewColorable(w), nil), + ) + +[zerolog.ConsoleWriter]: https://pkg.go.dev/github.com/rs/zerolog#ConsoleWriter +[go-isatty]: https://pkg.go.dev/github.com/mattn/go-isatty +[go-colorable]: https://pkg.go.dev/github.com/mattn/go-colorable +*/ +package tint + +import ( + "context" + "encoding" + "fmt" + "io" + "log/slog" + "path/filepath" + "runtime" + "strconv" + "sync" + "time" + "unicode" +) + +// ANSI modes +const ( + ansiReset = "\033[0m" + ansiFaint = "\033[2m" + ansiBrightRed = "\033[91m" + ansiBrightGreen = "\033[92m" + ansiBrightYellow = "\033[93m" + ansiBrightRedFaint = "\033[91;2m" +) + +const errKey = "err" + +var ( + defaultLevel = slog.LevelInfo + defaultTimeFormat = time.StampMilli + defaultLevelColors = map[slog.Level]string{ + slog.LevelDebug: ansiFaint, + slog.LevelInfo: ansiBrightGreen, + slog.LevelWarn: ansiBrightYellow, + slog.LevelError: ansiBrightRed, + } + defaultColors = map[Kind]string{ + KindTime: ansiFaint, + KindSourceFile: ansiFaint, + KindSourceSeparator: ansiFaint, + KindSourceLine: ansiFaint, + KindMessage: "", + KindKey: ansiFaint, + KindSeparator: ansiFaint, + KindValue: "", + KindErrorKey: ansiBrightRedFaint, + KindErrorSeparator: ansiBrightRedFaint, + KindErrorValue: ansiBrightRed, + } +) + +type Kind int + +const ( + KindTime Kind = iota + KindSourceFile + KindSourceSeparator + KindSourceLine + KindMessage + KindKey + KindSeparator + KindValue + KindErrorKey + KindErrorSeparator + KindErrorValue +) + +// Options for a slog.Handler that writes tinted logs. A zero Options consists +// entirely of default values. +// +// Options can be used as a drop-in replacement for [slog.HandlerOptions]. +type Options struct { + // Enable source code location (Default: false) + AddSource bool + + // Minimum level to log (Default: slog.LevelInfo) + Level slog.Leveler + + // ReplaceAttr is called to rewrite each non-group attribute before it is logged. + // See https://pkg.go.dev/log/slog#HandlerOptions for details. + ReplaceAttr func(groups []string, attr slog.Attr) slog.Attr + + // Time format (Default: time.StampMilli) + TimeFormat string + + // Disable color (Default: false) + NoColor bool + + // Level colors (Default: debug: faint, info: green, warn: yellow, error: red) + LevelColors map[slog.Level]string + + // Colors of certain parts of the log message + Colors map[Kind]string +} + +// NewHandler creates a [slog.Handler] that writes tinted logs to Writer w, +// using the default options. If opts is nil, the default options are used. +func NewHandler(w io.Writer, opts *Options) slog.Handler { + h := &handler{ + w: w, + level: defaultLevel, + timeFormat: defaultTimeFormat, + levelColors: defaultLevelColors, + colors: defaultColors, + } + if opts == nil { + return h + } + + h.addSource = opts.AddSource + if opts.Level != nil { + h.level = opts.Level + } + h.replaceAttr = opts.ReplaceAttr + if opts.TimeFormat != "" { + h.timeFormat = opts.TimeFormat + } + h.noColor = opts.NoColor + if opts.LevelColors != nil { + h.levelColors = opts.LevelColors + } + if opts.Colors != nil { + h.colors = opts.Colors + } + return h +} + +// handler implements a [slog.Handler]. +type handler struct { + attrsPrefix string + groupPrefix string + groups []string + + mu sync.Mutex + w io.Writer + + addSource bool + level slog.Leveler + replaceAttr func([]string, slog.Attr) slog.Attr + timeFormat string + noColor bool + levelColors map[slog.Level]string + colors map[Kind]string +} + +func (h *handler) clone() *handler { + return &handler{ + attrsPrefix: h.attrsPrefix, + groupPrefix: h.groupPrefix, + groups: h.groups, + w: h.w, + addSource: h.addSource, + level: h.level, + replaceAttr: h.replaceAttr, + timeFormat: h.timeFormat, + noColor: h.noColor, + levelColors: h.levelColors, + colors: h.colors, + } +} + +func (h *handler) Enabled(_ context.Context, level slog.Level) bool { + return level >= h.level.Level() +} + +func (h *handler) Handle(_ context.Context, r slog.Record) error { + // get a buffer from the sync pool + buf := newBuffer() + defer buf.Free() + + rep := h.replaceAttr + + // write time + if !r.Time.IsZero() { + val := r.Time.Round(0) // strip monotonic to match Attr behavior + if rep == nil { + h.appendTime(buf, r.Time) + buf.WriteByte(' ') + } else if a := rep(nil /* groups */, slog.Time(slog.TimeKey, val)); a.Key != "" { + if a.Value.Kind() == slog.KindTime { + h.appendTime(buf, a.Value.Time()) + } else { + h.appendValue(buf, a.Value, false) + } + buf.WriteByte(' ') + } + } + + // write level + if rep == nil { + h.appendLevel(buf, r.Level) + buf.WriteByte(' ') + } else if a := rep(nil /* groups */, slog.Any(slog.LevelKey, r.Level)); a.Key != "" { + h.appendValue(buf, a.Value, false) + buf.WriteByte(' ') + } + + // write source + if h.addSource { + fs := runtime.CallersFrames([]uintptr{r.PC}) + f, _ := fs.Next() + if f.File != "" { + src := &slog.Source{ + Function: f.Function, + File: f.File, + Line: f.Line, + } + + if rep == nil { + h.appendSource(buf, src) + buf.WriteByte(' ') + } else if a := rep(nil /* groups */, slog.Any(slog.SourceKey, src)); a.Key != "" { + h.appendValue(buf, a.Value, false) + buf.WriteByte(' ') + } + } + } + + // write message + if rep == nil { + buf.WriteStringIf(!h.noColor, h.colors[KindMessage]) + buf.WriteString(r.Message) + buf.WriteStringIf(!h.noColor, ansiReset) + buf.WriteByte(' ') + } else if a := rep(nil /* groups */, slog.String(slog.MessageKey, r.Message)); a.Key != "" { + h.appendValue(buf, a.Value, false) + buf.WriteByte(' ') + } + + // write handler attributes + if len(h.attrsPrefix) > 0 { + buf.WriteString(h.attrsPrefix) + } + + // write attributes + r.Attrs(func(attr slog.Attr) bool { + h.appendAttr(buf, attr, h.groupPrefix, h.groups) + return true + }) + + if len(*buf) == 0 { + return nil + } + (*buf)[len(*buf)-1] = '\n' // replace last space with newline + + h.mu.Lock() + defer h.mu.Unlock() + + _, err := h.w.Write(*buf) + return err +} + +func (h *handler) WithAttrs(attrs []slog.Attr) slog.Handler { + if len(attrs) == 0 { + return h + } + h2 := h.clone() + + buf := newBuffer() + defer buf.Free() + + // write attributes to buffer + for _, attr := range attrs { + h.appendAttr(buf, attr, h.groupPrefix, h.groups) + } + h2.attrsPrefix = h.attrsPrefix + string(*buf) + return h2 +} + +func (h *handler) WithGroup(name string) slog.Handler { + if name == "" { + return h + } + h2 := h.clone() + h2.groupPrefix += name + "." + h2.groups = append(h2.groups, name) + return h2 +} + +func (h *handler) appendTime(buf *buffer, t time.Time) { + buf.WriteStringIf(!h.noColor, h.colors[KindTime]) + *buf = t.AppendFormat(*buf, h.timeFormat) + buf.WriteStringIf(!h.noColor, ansiReset) +} + +func (h *handler) appendLevel(buf *buffer, level slog.Level) { + switch { + case level < slog.LevelInfo: + buf.WriteStringIf(!h.noColor, h.levelColors[level]) + buf.WriteString("DBG") + appendLevelDelta(buf, level-slog.LevelDebug) + buf.WriteStringIf(!h.noColor, ansiReset) + case level < slog.LevelWarn: + buf.WriteStringIf(!h.noColor, h.levelColors[level]) + buf.WriteString("INF") + appendLevelDelta(buf, level-slog.LevelInfo) + buf.WriteStringIf(!h.noColor, ansiReset) + case level < slog.LevelError: + buf.WriteStringIf(!h.noColor, h.levelColors[level]) + buf.WriteString("WRN") + appendLevelDelta(buf, level-slog.LevelWarn) + buf.WriteStringIf(!h.noColor, ansiReset) + default: + buf.WriteStringIf(!h.noColor, h.levelColors[level]) + buf.WriteString("ERR") + appendLevelDelta(buf, level-slog.LevelError) + buf.WriteStringIf(!h.noColor, ansiReset) + } +} + +func appendLevelDelta(buf *buffer, delta slog.Level) { + if delta == 0 { + return + } else if delta > 0 { + buf.WriteByte('+') + } + *buf = strconv.AppendInt(*buf, int64(delta), 10) +} + +func (h *handler) appendSource(buf *buffer, src *slog.Source) { + dir, file := filepath.Split(src.File) + + buf.WriteStringIf(!h.noColor, h.colors[KindSourceFile]) + buf.WriteString(filepath.Join(filepath.Base(dir), file)) + buf.WriteStringIf(!h.noColor, ansiReset+h.colors[KindSourceSeparator]) + buf.WriteByte(':') + buf.WriteStringIf(!h.noColor, ansiReset+h.colors[KindSourceLine]) + buf.WriteString(strconv.Itoa(src.Line)) + buf.WriteStringIf(!h.noColor, ansiReset) +} + +func (h *handler) appendAttr(buf *buffer, attr slog.Attr, groupsPrefix string, groups []string) { + attr.Value = attr.Value.Resolve() + if rep := h.replaceAttr; rep != nil && attr.Value.Kind() != slog.KindGroup { + attr = rep(groups, attr) + attr.Value = attr.Value.Resolve() + } + + if attr.Equal(slog.Attr{}) { + return + } + + if attr.Value.Kind() == slog.KindGroup { + if attr.Key != "" { + groupsPrefix += attr.Key + "." + groups = append(groups, attr.Key) + } + for _, groupAttr := range attr.Value.Group() { + h.appendAttr(buf, groupAttr, groupsPrefix, groups) + } + } else if err, ok := attr.Value.Any().(error); ok && attr.Key == errKey { + h.appendError(buf, err, groupsPrefix) + buf.WriteByte(' ') + } else { + h.appendKey(buf, attr.Key, groupsPrefix) + h.appendValue(buf, attr.Value, true) + buf.WriteByte(' ') + } +} + +func (h *handler) appendKey(buf *buffer, key, groups string) { + buf.WriteStringIf(!h.noColor, h.colors[KindKey]) + appendString(buf, groups+key, true) + buf.WriteStringIf(!h.noColor, ansiReset+h.colors[KindSeparator]) + buf.WriteByte('=') + buf.WriteStringIf(!h.noColor, ansiReset) +} + +func (h *handler) appendValue(buf *buffer, v slog.Value, quote bool) { + buf.WriteStringIf(!h.noColor, h.colors[KindValue]) + switch v.Kind() { + case slog.KindString: + appendString(buf, v.String(), quote) + case slog.KindInt64: + *buf = strconv.AppendInt(*buf, v.Int64(), 10) + case slog.KindUint64: + *buf = strconv.AppendUint(*buf, v.Uint64(), 10) + case slog.KindFloat64: + *buf = strconv.AppendFloat(*buf, v.Float64(), 'g', -1, 64) + case slog.KindBool: + *buf = strconv.AppendBool(*buf, v.Bool()) + case slog.KindDuration: + appendString(buf, v.Duration().String(), quote) + case slog.KindTime: + appendString(buf, v.Time().String(), quote) + case slog.KindAny: + switch cv := v.Any().(type) { + case slog.Level: + h.appendLevel(buf, cv) + case encoding.TextMarshaler: + data, err := cv.MarshalText() + if err != nil { + break + } + appendString(buf, string(data), quote) + case *slog.Source: + h.appendSource(buf, cv) + default: + appendString(buf, fmt.Sprintf("%+v", v.Any()), quote) + } + } + buf.WriteStringIf(!h.noColor, ansiReset) +} + +func (h *handler) appendError(buf *buffer, err error, groupsPrefix string) { + buf.WriteStringIf(!h.noColor, h.colors[KindErrorKey]) + appendString(buf, groupsPrefix+errKey, true) + buf.WriteStringIf(!h.noColor, ansiReset+h.colors[KindErrorSeparator]) + buf.WriteByte('=') + buf.WriteStringIf(!h.noColor, ansiReset+h.colors[KindErrorValue]) + appendString(buf, err.Error(), true) + buf.WriteStringIf(!h.noColor, ansiReset) +} + +func appendString(buf *buffer, s string, quote bool) { + if quote && needsQuoting(s) { + *buf = strconv.AppendQuote(*buf, s) + } else { + buf.WriteString(s) + } +} + +func needsQuoting(s string) bool { + if len(s) == 0 { + return true + } + for _, r := range s { + if unicode.IsSpace(r) || r == '"' || r == '=' || !unicode.IsPrint(r) { + return true + } + } + return false +} + +// Err returns slog.Any("err", err) +func Err(err error) slog.Attr { + return slog.Any(errKey, err) +} diff --git a/handler_test.go b/handler_test.go new file mode 100644 index 0000000..1a1b882 --- /dev/null +++ b/handler_test.go @@ -0,0 +1,581 @@ +package tint_test + +import ( + "bytes" + "context" + "errors" + "io" + "log/slog" + "os" + "slices" + "strconv" + "strings" + "testing" + "time" + + "toastielab.dev/toastie-stuff/tint" +) + +var faketime = time.Date(2009, time.November, 10, 23, 0, 0, 0, time.UTC) + +func Example() { + slog.SetDefault(slog.New(tint.NewHandler(os.Stderr, &tint.Options{ + Level: slog.LevelDebug, + TimeFormat: time.Kitchen, + }))) + + slog.Info("Starting server", "addr", ":8080", "env", "production") + slog.Debug("Connected to DB", "db", "myapp", "host", "localhost:5432") + slog.Warn("Slow request", "method", "GET", "path", "/users", "duration", 497*time.Millisecond) + slog.Error("DB connection lost", tint.Err(errors.New("connection reset")), "db", "myapp") + // Output: +} + +// Run test with "faketime" tag: +// +// TZ="" go test -tags=faketime +func TestHandler(t *testing.T) { + if !faketime.Equal(time.Now()) { + t.Skip(`skipping test; run with "-tags=faketime"`) + } + + tests := []struct { + Opts *tint.Options + F func(l *slog.Logger) + Want string + }{ + { + F: func(l *slog.Logger) { + l.Info("test", "key", "val") + }, + Want: `Nov 10 23:00:00.000 INF test key=val`, + }, + { + F: func(l *slog.Logger) { + l.Error("test", tint.Err(errors.New("fail"))) + }, + Want: `Nov 10 23:00:00.000 ERR test err=fail`, + }, + { + F: func(l *slog.Logger) { + l.Info("test", slog.Group("group", slog.String("key", "val"), tint.Err(errors.New("fail")))) + }, + Want: `Nov 10 23:00:00.000 INF test group.key=val group.err=fail`, + }, + { + F: func(l *slog.Logger) { + l.WithGroup("group").Info("test", "key", "val") + }, + Want: `Nov 10 23:00:00.000 INF test group.key=val`, + }, + { + F: func(l *slog.Logger) { + l.With("key", "val").Info("test", "key2", "val2") + }, + Want: `Nov 10 23:00:00.000 INF test key=val key2=val2`, + }, + { + F: func(l *slog.Logger) { + l.Info("test", "k e y", "v a l") + }, + Want: `Nov 10 23:00:00.000 INF test "k e y"="v a l"`, + }, + { + F: func(l *slog.Logger) { + l.WithGroup("g r o u p").Info("test", "key", "val") + }, + Want: `Nov 10 23:00:00.000 INF test "g r o u p.key"=val`, + }, + { + F: func(l *slog.Logger) { + l.Info("test", "slice", []string{"a", "b", "c"}, "map", map[string]int{"a": 1, "b": 2, "c": 3}) + }, + Want: `Nov 10 23:00:00.000 INF test slice="[a b c]" map="map[a:1 b:2 c:3]"`, + }, + { + Opts: &tint.Options{ + AddSource: true, + }, + F: func(l *slog.Logger) { + l.Info("test", "key", "val") + }, + Want: `Nov 10 23:00:00.000 INF tint/handler_test.go:100 test key=val`, + }, + { + Opts: &tint.Options{ + TimeFormat: time.Kitchen, + }, + F: func(l *slog.Logger) { + l.Info("test", "key", "val") + }, + Want: `11:00PM INF test key=val`, + }, + { + Opts: &tint.Options{ + ReplaceAttr: drop(slog.TimeKey), + }, + F: func(l *slog.Logger) { + l.Info("test", "key", "val") + }, + Want: `INF test key=val`, + }, + { + Opts: &tint.Options{ + ReplaceAttr: drop(slog.LevelKey), + }, + F: func(l *slog.Logger) { + l.Info("test", "key", "val") + }, + Want: `Nov 10 23:00:00.000 test key=val`, + }, + { + Opts: &tint.Options{ + ReplaceAttr: drop(slog.MessageKey), + }, + F: func(l *slog.Logger) { + l.Info("test", "key", "val") + }, + Want: `Nov 10 23:00:00.000 INF key=val`, + }, + { + Opts: &tint.Options{ + ReplaceAttr: drop(slog.TimeKey, slog.LevelKey, slog.MessageKey), + }, + F: func(l *slog.Logger) { + l.Info("test", "key", "val") + }, + Want: `key=val`, + }, + { + Opts: &tint.Options{ + ReplaceAttr: drop("key"), + }, + F: func(l *slog.Logger) { + l.Info("test", "key", "val") + }, + Want: `Nov 10 23:00:00.000 INF test`, + }, + { + Opts: &tint.Options{ + ReplaceAttr: drop("key"), + }, + F: func(l *slog.Logger) { + l.WithGroup("group").Info("test", "key", "val", "key2", "val2") + }, + Want: `Nov 10 23:00:00.000 INF test group.key=val group.key2=val2`, + }, + { + Opts: &tint.Options{ + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + if a.Key == "key" && len(groups) == 1 && groups[0] == "group" { + return slog.Attr{} + } + return a + }, + }, + F: func(l *slog.Logger) { + l.WithGroup("group").Info("test", "key", "val", "key2", "val2") + }, + Want: `Nov 10 23:00:00.000 INF test group.key2=val2`, + }, + { + Opts: &tint.Options{ + ReplaceAttr: replace(slog.IntValue(42), slog.TimeKey), + }, + F: func(l *slog.Logger) { + l.Info("test", "key", "val") + }, + Want: `42 INF test key=val`, + }, + { + Opts: &tint.Options{ + ReplaceAttr: replace(slog.StringValue("INFO"), slog.LevelKey), + }, + F: func(l *slog.Logger) { + l.Info("test", "key", "val") + }, + Want: `Nov 10 23:00:00.000 INFO test key=val`, + }, + { + Opts: &tint.Options{ + ReplaceAttr: replace(slog.IntValue(42), slog.MessageKey), + }, + F: func(l *slog.Logger) { + l.Info("test", "key", "val") + }, + Want: `Nov 10 23:00:00.000 INF 42 key=val`, + }, + { + Opts: &tint.Options{ + ReplaceAttr: replace(slog.IntValue(42), "key"), + }, + F: func(l *slog.Logger) { + l.With("key", "val").Info("test", "key2", "val2") + }, + Want: `Nov 10 23:00:00.000 INF test key=42 key2=val2`, + }, + { + Opts: &tint.Options{ + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + return slog.Attr{} + }, + }, + F: func(l *slog.Logger) { + l.Info("test", "key", "val") + }, + Want: ``, + }, + { + F: func(l *slog.Logger) { + l.Info("test", "key", "") + }, + Want: `Nov 10 23:00:00.000 INF test key=""`, + }, + { + F: func(l *slog.Logger) { + l.Info("test", "", "val") + }, + Want: `Nov 10 23:00:00.000 INF test ""=val`, + }, + { + F: func(l *slog.Logger) { + l.Info("test", "", "") + }, + Want: `Nov 10 23:00:00.000 INF test ""=""`, + }, + + { // https://toastielab.dev/toastie-stuff/tint/issues/8 + F: func(l *slog.Logger) { + l.Log(context.TODO(), slog.LevelInfo+1, "test") + }, + Want: `Nov 10 23:00:00.000 INF+1 test`, + }, + { + Opts: &tint.Options{ + Level: slog.LevelDebug - 1, + }, + F: func(l *slog.Logger) { + l.Log(context.TODO(), slog.LevelDebug-1, "test") + }, + Want: `Nov 10 23:00:00.000 DBG-1 test`, + }, + { // https://toastielab.dev/toastie-stuff/tint/issues/12 + F: func(l *slog.Logger) { + l.Error("test", slog.Any("error", errors.New("fail"))) + }, + Want: `Nov 10 23:00:00.000 ERR test error=fail`, + }, + { // https://toastielab.dev/toastie-stuff/tint/issues/15 + F: func(l *slog.Logger) { + l.Error("test", tint.Err(nil)) + }, + Want: `Nov 10 23:00:00.000 ERR test err=<nil>`, + }, + { // https://toastielab.dev/toastie-stuff/tint/pull/26 + Opts: &tint.Options{ + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + if a.Key == slog.TimeKey && len(groups) == 0 { + return slog.Time(slog.TimeKey, a.Value.Time().Add(24*time.Hour)) + } + return a + }, + }, + F: func(l *slog.Logger) { + l.Error("test") + }, + Want: `Nov 11 23:00:00.000 ERR test`, + }, + { // https://toastielab.dev/toastie-stuff/tint/pull/27 + F: func(l *slog.Logger) { + l.Info("test", "a", "b", slog.Group("", slog.String("c", "d")), "e", "f") + }, + Want: `Nov 10 23:00:00.000 INF test a=b c=d e=f`, + }, + { // https://toastielab.dev/toastie-stuff/tint/pull/30 + // drop built-in attributes in a grouped log + Opts: &tint.Options{ + ReplaceAttr: drop(slog.TimeKey, slog.LevelKey, slog.MessageKey, slog.SourceKey), + AddSource: true, + }, + F: func(l *slog.Logger) { + l.WithGroup("group").Info("test", "key", "val") + }, + Want: `group.key=val`, + }, + { // https://toastielab.dev/toastie-stuff/tint/issues/36 + Opts: &tint.Options{ + ReplaceAttr: func(g []string, a slog.Attr) slog.Attr { + if len(g) == 0 && a.Key == slog.LevelKey { + _ = a.Value.Any().(slog.Level) + } + return a + }, + }, + F: func(l *slog.Logger) { + l.Info("test") + }, + Want: `Nov 10 23:00:00.000 INF test`, + }, + { // https://toastielab.dev/toastie-stuff/tint/issues/37 + Opts: &tint.Options{ + AddSource: true, + ReplaceAttr: func(g []string, a slog.Attr) slog.Attr { + return a + }, + }, + F: func(l *slog.Logger) { + l.Info("test") + }, + Want: `Nov 10 23:00:00.000 INF tint/handler_test.go:327 test`, + }, + { // https://toastielab.dev/toastie-stuff/tint/issues/44 + F: func(l *slog.Logger) { + l = l.WithGroup("group") + l.Error("test", tint.Err(errTest)) + }, + Want: `Nov 10 23:00:00.000 ERR test group.err=fail`, + }, + { // https://github.com/lmittmann/tint/issues/55 + F: func(l *slog.Logger) { + l.Info("test", "key", struct { + A int + B *string + }{A: 123}) + }, + Want: `Nov 10 23:00:00.000 INF test key="{A:123 B:<nil>}"`, + }, + } + + for i, test := range tests { + t.Run(strconv.Itoa(i), func(t *testing.T) { + var buf bytes.Buffer + if test.Opts == nil { + test.Opts = &tint.Options{} + } + test.Opts.NoColor = true + l := slog.New(tint.NewHandler(&buf, test.Opts)) + test.F(l) + + got := strings.TrimRight(buf.String(), "\n") + if test.Want != got { + t.Fatalf("(-want +got)\n- %s\n+ %s", test.Want, got) + } + }) + } +} + +// drop returns a ReplaceAttr that drops the given keys. +func drop(keys ...string) func([]string, slog.Attr) slog.Attr { + return func(groups []string, a slog.Attr) slog.Attr { + if len(groups) > 0 { + return a + } + + for _, key := range keys { + if a.Key == key { + a = slog.Attr{} + } + } + return a + } +} + +func replace(new slog.Value, keys ...string) func([]string, slog.Attr) slog.Attr { + return func(groups []string, a slog.Attr) slog.Attr { + if len(groups) > 0 { + return a + } + + for _, key := range keys { + if a.Key == key { + a.Value = new + } + } + return a + } +} + +func TestReplaceAttr(t *testing.T) { + tests := [][]any{ + {}, + {"key", "val"}, + {"key", "val", slog.Group("group", "key2", "val2")}, + {"key", "val", slog.Group("group", "key2", "val2", slog.Group("group2", "key3", "val3"))}, + } + + type replaceAttrParams struct { + Groups []string + Attr slog.Attr + } + + replaceAttrRecorder := func(record *[]replaceAttrParams) func([]string, slog.Attr) slog.Attr { + return func(groups []string, a slog.Attr) slog.Attr { + *record = append(*record, replaceAttrParams{groups, a}) + return a + } + } + + for i, test := range tests { + t.Run(strconv.Itoa(i), func(t *testing.T) { + slogRecord := make([]replaceAttrParams, 0) + slogLogger := slog.New(slog.NewTextHandler(io.Discard, &slog.HandlerOptions{ + ReplaceAttr: replaceAttrRecorder(&slogRecord), + })) + slogLogger.Log(context.TODO(), slog.LevelInfo, "", test...) + + tintRecord := make([]replaceAttrParams, 0) + tintLogger := slog.New(tint.NewHandler(io.Discard, &tint.Options{ + ReplaceAttr: replaceAttrRecorder(&tintRecord), + })) + tintLogger.Log(context.TODO(), slog.LevelInfo, "", test...) + + if !slices.EqualFunc(slogRecord, tintRecord, func(a, b replaceAttrParams) bool { + return slices.Equal(a.Groups, b.Groups) && a.Attr.Equal(b.Attr) + }) { + t.Fatalf("(-want +got)\n- %v\n+ %v", slogRecord, tintRecord) + } + }) + } +} + +// See https://github.com/golang/exp/blob/master/slog/benchmarks/benchmarks_test.go#L25 +// +// Run e.g.: +// +// go test -bench=. -count=10 | benchstat -col /h /dev/stdin +func BenchmarkLogAttrs(b *testing.B) { + handler := []struct { + Name string + H slog.Handler + }{ + {"tint", tint.NewHandler(io.Discard, nil)}, + {"text", slog.NewTextHandler(io.Discard, nil)}, + {"json", slog.NewJSONHandler(io.Discard, nil)}, + {"discard", new(discarder)}, + } + + benchmarks := []struct { + Name string + F func(*slog.Logger) + }{ + { + "5 args", + func(logger *slog.Logger) { + logger.LogAttrs(context.TODO(), slog.LevelInfo, testMessage, + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", errTest), + ) + }, + }, + { + "5 args custom level", + func(logger *slog.Logger) { + logger.LogAttrs(context.TODO(), slog.LevelInfo+1, testMessage, + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", errTest), + ) + }, + }, + { + "10 args", + func(logger *slog.Logger) { + logger.LogAttrs(context.TODO(), slog.LevelInfo, testMessage, + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", errTest), + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", errTest), + ) + }, + }, + { + "40 args", + func(logger *slog.Logger) { + logger.LogAttrs(context.TODO(), slog.LevelInfo, testMessage, + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", errTest), + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", errTest), + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", errTest), + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", errTest), + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", errTest), + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", errTest), + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", errTest), + slog.String("string", testString), + slog.Int("status", testInt), + slog.Duration("duration", testDuration), + slog.Time("time", testTime), + slog.Any("error", errTest), + ) + }, + }, + } + + for _, h := range handler { + b.Run("h="+h.Name, func(b *testing.B) { + for _, bench := range benchmarks { + b.Run(bench.Name, func(b *testing.B) { + b.ReportAllocs() + logger := slog.New(h.H) + for i := 0; i < b.N; i++ { + bench.F(logger) + } + }) + } + }) + } +} + +// discarder is a slog.Handler that discards all records. +type discarder struct{} + +func (*discarder) Enabled(context.Context, slog.Level) bool { return true } +func (*discarder) Handle(context.Context, slog.Record) error { return nil } +func (d *discarder) WithAttrs(attrs []slog.Attr) slog.Handler { return d } +func (d *discarder) WithGroup(name string) slog.Handler { return d } + +var ( + testMessage = "Test logging, but use a somewhat realistic message length." + testTime = time.Date(2022, time.May, 1, 0, 0, 0, 0, time.UTC) + testString = "7e3b3b2aaeff56a7108fe11e154200dd/7819479873059528190" + testInt = 32768 + testDuration = 23 * time.Second + errTest = errors.New("fail") +)