From de5e6b7ea61112d18858b372fc8c868cfdf95628 Mon Sep 17 00:00:00 2001 From: lmittmann <3458786+lmittmann@users.noreply.github.com> Date: Mon, 26 May 2025 22:06:06 +0200 Subject: [PATCH 1/3] Fix time attribute formatting to match `slog.TextHandler` (#94) * fix skip condition + restructure regression tests * added `slog.TextHandler` comparison test * fixed format differences in how time values are logged * fix missing newline if no args are logged * improve `TestHandler` to check for newline + added time formatting testcase * drop obsolete `TestFormat` --------- Co-authored-by: lmittmann --- handler.go | 23 +++++++++++++++++++---- handler_test.go | 46 +++++++++++++++++++++++++++------------------- 2 files changed, 46 insertions(+), 23 deletions(-) diff --git a/handler.go b/handler.go index fb7203b..1c8d770 100644 --- a/handler.go +++ b/handler.go @@ -296,9 +296,10 @@ func (h *handler) Handle(_ context.Context, r slog.Record) error { }) if len(*buf) == 0 { - return nil + buf.WriteByte('\n') + } else { + (*buf)[len(*buf)-1] = '\n' // replace last space with newline } - (*buf)[len(*buf)-1] = '\n' // replace last space with newline h.mu.Lock() defer h.mu.Unlock() @@ -470,7 +471,7 @@ func (h *handler) appendValue(buf *buffer, v slog.Value, quote bool) { case slog.KindDuration: appendString(buf, v.Duration().String(), quote, !h.noColor) case slog.KindTime: - appendString(buf, v.Time().String(), quote, !h.noColor) + *buf = appendRFC3339Millis(*buf, v.Time()) case slog.KindAny: defer func() { // Copied from log/slog/handler.go. @@ -481,7 +482,7 @@ func (h *handler) appendValue(buf *buffer, v slog.Value, quote bool) { // // Adapted from the code in fmt/print.go. if v := reflect.ValueOf(v.Any()); v.Kind() == reflect.Pointer && v.IsNil() { - appendString(buf, "", false, false) + buf.WriteString("") return } @@ -521,6 +522,20 @@ func (h *handler) appendTintValue(buf *buffer, val slog.Value, quote bool, color } } +// Copied from log/slog/handler.go. +func appendRFC3339Millis(b []byte, t time.Time) []byte { + // Format according to time.RFC3339Nano since it is highly optimized, + // but truncate it to use millisecond resolution. + // Unfortunately, that format trims trailing 0s, so add 1/10 millisecond + // to guarantee that there are exactly 4 digits after the period. + const prefixLen = len("2006-01-02T15:04:05.000") + n := len(b) + t = t.Truncate(time.Millisecond).Add(time.Millisecond / 10) + b = t.AppendFormat(b, time.RFC3339Nano) + b = append(b[:n+prefixLen], b[n+prefixLen+1:]...) // drop the 4th digit + return b +} + func appendAnsi(buf *buffer, color uint8, faint bool) { buf.WriteString("\u001b[") if faint { diff --git a/handler_test.go b/handler_test.go index 8a24150..f847cc0 100644 --- a/handler_test.go +++ b/handler_test.go @@ -16,8 +16,6 @@ import ( "github.com/lmittmann/tint" ) -var faketime = time.Date(2009, time.November, 10, 23, 0, 0, 0, time.UTC) - func Example() { w := os.Stderr logger := slog.New(tint.NewHandler(w, &tint.Options{ @@ -69,15 +67,10 @@ func Example_traceLevel() { // 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"`) - } +var ( + faketime = time.Date(2009, time.November, 10, 23, 0, 0, 0, time.UTC) - tests := []struct { + handlerTests = []struct { Opts *tint.Options F func(l *slog.Logger) Want string @@ -138,7 +131,7 @@ func TestHandler(t *testing.T) { F: func(l *slog.Logger) { l.Info("test", "key", "val") }, - Want: `Nov 10 23:00:00.000 INF tint/handler_test.go:139 test key=val`, + Want: `Nov 10 23:00:00.000 INF tint/handler_test.go:132 test key=val`, }, { Opts: &tint.Options{ @@ -415,7 +408,7 @@ func TestHandler(t *testing.T) { F: func(l *slog.Logger) { l.Info("test") }, - Want: "\033[2mNov 10 23:00:00.000\033[0m \033[92mINF\033[0m \033[2;92mtint/handler_test.go:416\033[0m test", + Want: "\033[2mNov 10 23:00:00.000\033[0m \033[92mINF\033[0m \033[2;92mtint/handler_test.go:409\033[0m test", }, { Opts: &tint.Options{ @@ -545,7 +538,7 @@ func TestHandler(t *testing.T) { F: func(l *slog.Logger) { l.Info("test") }, - Want: `Nov 10 23:00:00.000 INF tint/handler_test.go:546 test`, + Want: `Nov 10 23:00:00.000 INF tint/handler_test.go:539 test`, }, { // https://github.com/lmittmann/tint/issues/44 F: func(l *slog.Logger) { @@ -606,9 +599,21 @@ func TestHandler(t *testing.T) { }, Want: `Nov 10 23:00:00.000 INF test time=`, }, + { // https://github.com/lmittmann/tint/pull/94 + F: func(l *slog.Logger) { + l.Info("test", "time", testTime) + }, + Want: `Nov 10 23:00:00.000 INF test time=2022-05-01T00:00:00.000Z`, + }, } +) - for i, test := range tests { +func TestHandler(t *testing.T) { + if now := time.Now(); !faketime.Equal(now) || now.Location().String() != "UTC" { + t.Skip(`run: TZ="" go test -tags=faketime`) + } + + for i, test := range handlerTests { t.Run(strconv.Itoa(i), func(t *testing.T) { var buf bytes.Buffer if test.Opts == nil { @@ -617,7 +622,10 @@ func TestHandler(t *testing.T) { l := slog.New(tint.NewHandler(&buf, test.Opts)) test.F(l) - got := strings.TrimRight(buf.String(), "\n") + got, foundNewline := strings.CutSuffix(buf.String(), "\n") + if !foundNewline { + t.Fatalf("missing newline") + } if test.Want != got { t.Fatalf("(-want +got)\n- %s\n+ %s", test.Want, got) } @@ -657,8 +665,8 @@ func replace(new slog.Value, keys ...string) func([]string, slog.Attr) slog.Attr } func TestReplaceAttr(t *testing.T) { - if !faketime.Equal(time.Now()) { - t.Skip(`skipping test; run with "-tags=faketime"`) + if now := time.Now(); !faketime.Equal(now) || now.Location().String() != "UTC" { + t.Skip(`run: TZ="" go test -tags=faketime`) } tests := [][]any{ @@ -704,8 +712,8 @@ func TestReplaceAttr(t *testing.T) { } func TestAttr(t *testing.T) { - if !faketime.Equal(time.Now()) { - t.Skip(`skipping test; run with "-tags=faketime"`) + if now := time.Now(); !faketime.Equal(now) || now.Location().String() != "UTC" { + t.Skip(`run: TZ="" go test -tags=faketime`) } t.Run("text", func(t *testing.T) { From ebaca5f418197ed7953d22ce2932d7bbf2af1a54 Mon Sep 17 00:00:00 2001 From: lmittmann <3458786+lmittmann@users.noreply.github.com> Date: Mon, 26 May 2025 22:41:49 +0200 Subject: [PATCH 2/3] Simplify `Options` storage in handler (#95) * cleanup * cleanup const --------- Co-authored-by: lmittmann --- handler.go | 88 +++++++++++++++++++++++------------------------------- 1 file changed, 38 insertions(+), 50 deletions(-) diff --git a/handler.go b/handler.go index 1c8d770..ac672f9 100644 --- a/handler.go +++ b/handler.go @@ -105,8 +105,9 @@ import ( "unicode/utf8" ) -// ANSI modes const ( + // ANSI modes + ansiEsc = '\u001b' ansiReset = "\u001b[0m" ansiFaint = "\u001b[2m" ansiResetFaint = "\u001b[22m" @@ -114,12 +115,8 @@ const ( ansiBrightGreen = "\u001b[92m" ansiBrightYellow = "\u001b[93m" - ansiEsc = '\u001b' -) - -const errKey = "err" + errKey = "err" -const ( defaultLevel = slog.LevelInfo defaultTimeFormat = time.StampMilli ) @@ -146,28 +143,27 @@ type Options struct { NoColor bool } +func (o *Options) setDefaults() { + if o.Level == nil { + o.Level = defaultLevel + } + if o.TimeFormat == "" { + o.TimeFormat = defaultTimeFormat + } +} + // 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, - } if opts == nil { - return h + opts = &Options{} } + opts.setDefaults() - h.addSource = opts.AddSource - if opts.Level != nil { - h.level = opts.Level - } - h.replaceAttr = opts.ReplaceAttr - if opts.TimeFormat != "" { - h.timeFormat = opts.TimeFormat + return &handler{ + w: w, + opts: *opts, } - h.noColor = opts.NoColor - return h } // handler implements a [slog.Handler]. @@ -179,11 +175,7 @@ type handler struct { mu sync.Mutex w io.Writer - addSource bool - level slog.Leveler - replaceAttr func([]string, slog.Attr) slog.Attr - timeFormat string - noColor bool + opts Options } func (h *handler) clone() *handler { @@ -192,16 +184,12 @@ func (h *handler) clone() *handler { groupPrefix: h.groupPrefix, groups: h.groups, w: h.w, - addSource: h.addSource, - level: h.level, - replaceAttr: h.replaceAttr, - timeFormat: h.timeFormat, - noColor: h.noColor, + opts: h.opts, } } func (h *handler) Enabled(_ context.Context, level slog.Level) bool { - return level >= h.level.Level() + return level >= h.opts.Level.Level() } func (h *handler) Handle(_ context.Context, r slog.Record) error { @@ -209,7 +197,7 @@ func (h *handler) Handle(_ context.Context, r slog.Record) error { buf := newBuffer() defer buf.Free() - rep := h.replaceAttr + rep := h.opts.ReplaceAttr // write time if !r.Time.IsZero() { @@ -247,7 +235,7 @@ func (h *handler) Handle(_ context.Context, r slog.Record) error { } // write source - if h.addSource { + if h.opts.AddSource { fs := runtime.CallersFrames([]uintptr{r.PC}) f, _ := fs.Next() if f.File != "" { @@ -258,7 +246,7 @@ func (h *handler) Handle(_ context.Context, r slog.Record) error { } if rep == nil { - if h.noColor { + if h.opts.NoColor { appendSource(buf, src) } else { buf.WriteString(ansiFaint) @@ -336,15 +324,15 @@ func (h *handler) WithGroup(name string) slog.Handler { } func (h *handler) appendTintTime(buf *buffer, t time.Time, color int16) { - if h.noColor { - *buf = t.AppendFormat(*buf, h.timeFormat) + if h.opts.NoColor { + *buf = t.AppendFormat(*buf, h.opts.TimeFormat) } else { if color >= 0 { appendAnsi(buf, uint8(color), true) } else { buf.WriteString(ansiFaint) } - *buf = t.AppendFormat(*buf, h.timeFormat) + *buf = t.AppendFormat(*buf, h.opts.TimeFormat) buf.WriteString(ansiReset) } } @@ -359,7 +347,7 @@ func (h *handler) appendTintLevel(buf *buffer, level slog.Level, color int16) { return strconv.AppendInt([]byte(base), int64(val), 10) } - if !h.noColor { + if !h.opts.NoColor { if color >= 0 { appendAnsi(buf, uint8(color), false) } else { @@ -386,7 +374,7 @@ func (h *handler) appendTintLevel(buf *buffer, level slog.Level, color int16) { buf.Write(str("ERR", level-slog.LevelError)) } - if !h.noColor && level >= slog.LevelInfo { + if !h.opts.NoColor && level >= slog.LevelInfo { buf.WriteString(ansiReset) } } @@ -400,7 +388,7 @@ func appendSource(buf *buffer, src *slog.Source) { } func (h *handler) resolve(val slog.Value) (resolvedVal slog.Value, color int16) { - if !h.noColor && val.Kind() == slog.KindLogValuer { + if !h.opts.NoColor && val.Kind() == slog.KindLogValuer { if tintVal, ok := val.Any().(tintValue); ok { return tintVal.Value.Resolve(), int16(tintVal.Color) } @@ -411,7 +399,7 @@ func (h *handler) resolve(val slog.Value) (resolvedVal slog.Value, color int16) func (h *handler) appendAttr(buf *buffer, attr slog.Attr, groupsPrefix string, groups []string) { var color int16 // -1 if no color attr.Value, color = h.resolve(attr.Value) - if rep := h.replaceAttr; rep != nil && attr.Value.Kind() != slog.KindGroup { + if rep := h.opts.ReplaceAttr; rep != nil && attr.Value.Kind() != slog.KindGroup { attr = rep(groups, attr) attr.Value, color = h.resolve(attr.Value) } @@ -431,7 +419,7 @@ func (h *handler) appendAttr(buf *buffer, attr slog.Attr, groupsPrefix string, g return } - if h.noColor { + if h.opts.NoColor { h.appendKey(buf, attr.Key, groupsPrefix) h.appendValue(buf, attr.Value, true) } else { @@ -452,14 +440,14 @@ func (h *handler) appendAttr(buf *buffer, attr slog.Attr, groupsPrefix string, g } func (h *handler) appendKey(buf *buffer, key, groups string) { - appendString(buf, groups+key, true, !h.noColor) + appendString(buf, groups+key, true, !h.opts.NoColor) buf.WriteByte('=') } func (h *handler) appendValue(buf *buffer, v slog.Value, quote bool) { switch v.Kind() { case slog.KindString: - appendString(buf, v.String(), quote, !h.noColor) + appendString(buf, v.String(), quote, !h.opts.NoColor) case slog.KindInt64: *buf = strconv.AppendInt(*buf, v.Int64(), 10) case slog.KindUint64: @@ -469,7 +457,7 @@ func (h *handler) appendValue(buf *buffer, v slog.Value, quote bool) { case slog.KindBool: *buf = strconv.AppendBool(*buf, v.Bool()) case slog.KindDuration: - appendString(buf, v.Duration().String(), quote, !h.noColor) + appendString(buf, v.Duration().String(), quote, !h.opts.NoColor) case slog.KindTime: *buf = appendRFC3339Millis(*buf, v.Time()) case slog.KindAny: @@ -487,7 +475,7 @@ func (h *handler) appendValue(buf *buffer, v slog.Value, quote bool) { } // Otherwise just print the original panic message. - appendString(buf, fmt.Sprintf("!PANIC: %v", r), true, !h.noColor) + appendString(buf, fmt.Sprintf("!PANIC: %v", r), true, !h.opts.NoColor) } }() @@ -497,17 +485,17 @@ func (h *handler) appendValue(buf *buffer, v slog.Value, quote bool) { if err != nil { break } - appendString(buf, string(data), quote, !h.noColor) + appendString(buf, string(data), quote, !h.opts.NoColor) case *slog.Source: appendSource(buf, cv) default: - appendString(buf, fmt.Sprintf("%+v", cv), quote, !h.noColor) + appendString(buf, fmt.Sprintf("%+v", cv), quote, !h.opts.NoColor) } } } func (h *handler) appendTintValue(buf *buffer, val slog.Value, quote bool, color int16, faint bool) { - if h.noColor { + if h.opts.NoColor { h.appendValue(buf, val, quote) } else { if color >= 0 { From 30257b8aa1086cba085a3321348a1b5aa2c2464d Mon Sep 17 00:00:00 2001 From: lmittmann <3458786+lmittmann@users.noreply.github.com> Date: Tue, 27 May 2025 22:55:15 +0200 Subject: [PATCH 3/3] Fix uncolored `tint.Attr` when `ReplaceAttr` is present (#96) * added testcase * added additional testcase * fix --------- Co-authored-by: lmittmann --- handler.go | 6 +++++- handler_test.go | 24 ++++++++++++++++++++++++ 2 files changed, 29 insertions(+), 1 deletion(-) diff --git a/handler.go b/handler.go index ac672f9..7ae4fa2 100644 --- a/handler.go +++ b/handler.go @@ -401,7 +401,11 @@ func (h *handler) appendAttr(buf *buffer, attr slog.Attr, groupsPrefix string, g attr.Value, color = h.resolve(attr.Value) if rep := h.opts.ReplaceAttr; rep != nil && attr.Value.Kind() != slog.KindGroup { attr = rep(groups, attr) - attr.Value, color = h.resolve(attr.Value) + var colorRep int16 + attr.Value, colorRep = h.resolve(attr.Value) + if colorRep >= 0 { + color = colorRep + } } if attr.Equal(slog.Attr{}) { diff --git a/handler_test.go b/handler_test.go index f847cc0..8ca35b7 100644 --- a/handler_test.go +++ b/handler_test.go @@ -605,6 +605,30 @@ var ( }, Want: `Nov 10 23:00:00.000 INF test time=2022-05-01T00:00:00.000Z`, }, + { // https://github.com/lmittmann/tint/pull/96 + Opts: &tint.Options{ + NoColor: false, + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + return a + }, + }, + F: func(l *slog.Logger) { + l.Info("test", tint.Attr(10, slog.String("key", "val"))) + }, + Want: "\033[2mNov 10 23:00:00.000\033[0m \033[92mINF\033[0m test \033[2;92mkey=\033[22mval\033[0m", + }, + { + Opts: &tint.Options{ + NoColor: false, + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + return tint.Attr(13, a) + }, + }, + F: func(l *slog.Logger) { + l.Info("test", tint.Attr(10, slog.String("key", "val"))) + }, + Want: "\033[2;95mNov 10 23:00:00.000\033[0m \033[95mINF\033[0m \033[95mtest\033[0m \033[2;95mkey=\033[22mval\033[0m", + }, } )