diff --git a/.github/workflows/go.yml b/.github/workflows/go.yml index bf6a993..c654b0b 100644 --- a/.github/workflows/go.yml +++ b/.github/workflows/go.yml @@ -1,31 +1,33 @@ -# This workflow will build a golang project -# For more information see: https://docs.github.com/en/actions/automating-builds-and-tests/building-and-testing-go - name: Build on: push: - branches: [ "main" ] + branches: [ master ] pull_request: - branches: [ "main" ] + branches: [ master ] + workflow_dispatch: jobs: - + lint: + runs-on: ubuntu-latest + steps: + - uses: actions/checkout@v4 + - uses: actions/setup-go@v5 + with: + go-version: stable + - uses: golangci/golangci-lint-action@v6 build: runs-on: ubuntu-latest + strategy: + matrix: + go: [ '^1.21', 'oldstable', 'stable' ] steps: - - uses: actions/checkout@v3 - - - name: Set up Go - uses: actions/setup-go@v4 + - uses: actions/setup-go@v5 with: - go-version: '1.21' - + go-version: ${{ matrix.go }} + - uses: actions/checkout@v4 - name: Build - run: go build -v ./... - + run: | + go build "./..." - name: Test - run: go test -race -coverprofile=coverage.txt -covermode=atomic -v ./... - - - name: Upload coverage to Codecov - uses: codecov/codecov-action@v3 \ No newline at end of file + run: go test -v -json ./... \ No newline at end of file diff --git a/README.md b/README.md index 193e151..cb96637 100644 --- a/README.md +++ b/README.md @@ -1,12 +1,12 @@ # console-slog -[![Go Reference](https://pkg.go.dev/badge/github.com/phsym/console-slog.svg)](https://pkg.go.dev/github.com/phsym/console-slog) [![license](http://img.shields.io/badge/license-MIT-red.svg?style=flat)](https://raw.githubusercontent.com/phsym/console-slog/master/LICENSE) [![Build](https://github.com/phsym/console-slog/actions/workflows/go.yml/badge.svg?branch=main)](https://github.com/phsym/slog-console/actions/workflows/go.yml) [![codecov](https://codecov.io/gh/phsym/console-slog/graph/badge.svg?token=ZIJT9L79QP)](https://codecov.io/gh/phsym/console-slog) [![Go Report Card](https://goreportcard.com/badge/github.com/phsym/console-slog)](https://goreportcard.com/report/github.com/phsym/console-slog) +[![Go Reference](https://pkg.go.dev/badge/github.com/ansel1/console-slog.svg)](https://pkg.go.dev/github.com/ansel1/console-slog) [![license](http://img.shields.io/badge/license-MIT-red.svg?style=flat)](https://raw.githubusercontent.com/ansel1/console-slog/master/LICENSE) [![Build](https://github.com/ansel1/console-slog/actions/workflows/go.yml/badge.svg?branch=main)](https://github.com/ansel1/slog-console/actions/workflows/go.yml) [![codecov](https://codecov.io/gh/ansel1/console-slog/graph/badge.svg?token=ZIJT9L79QP)](https://codecov.io/gh/ansel1/console-slog) [![Go Report Card](https://goreportcard.com/badge/github.com/ansel1/console-slog)](https://goreportcard.com/report/github.com/ansel1/console-slog) A handler for slog that prints colorized logs, similar to zerolog's console writer output without sacrificing performances. ## Installation ```bash -go get github.com/phsym/console-slog@latest +go get github.com/ansel1/console-slog@latest ``` ## Example @@ -18,7 +18,7 @@ import ( "log/slog" "os" - "github.com/phsym/console-slog" + "github.com/ansel1/console-slog" ) func main() { @@ -50,26 +50,9 @@ console.NewHandler(os.Stderr, &console.HandlerOptions{Level: slog.LevelDebug, Ad ## Performances See [benchmark file](./bench_test.go) for details. -The handler itself performs quite well compared to std-lib's handlers. It does no allocation: -``` -goos: linux -goarch: amd64 -pkg: github.com/phsym/console-slog -cpu: Intel(R) Core(TM) i5-6300U CPU @ 2.40GHz -BenchmarkHandlers/dummy-4 128931026 8.732 ns/op 0 B/op 0 allocs/op -BenchmarkHandlers/console-4 849837 1294 ns/op 0 B/op 0 allocs/op -BenchmarkHandlers/std-text-4 542583 2097 ns/op 4 B/op 2 allocs/op -BenchmarkHandlers/std-json-4 583784 1911 ns/op 120 B/op 3 allocs/op -``` +The handler itself performs quite well compared to std-lib's handlers. It does no allocation. It is generally faster +then slog.TextHandler, and a little slower than slog.JSONHandler. -However, the go 1.21.0 `slog.Logger` adds some overhead: -``` -goos: linux -goarch: amd64 -pkg: github.com/phsym/console-slog -cpu: Intel(R) Core(TM) i5-6300U CPU @ 2.40GHz -BenchmarkLoggers/dummy-4 1239873 893.2 ns/op 128 B/op 1 allocs/op -BenchmarkLoggers/console-4 483354 2338 ns/op 128 B/op 1 allocs/op -BenchmarkLoggers/std-text-4 368828 3141 ns/op 132 B/op 3 allocs/op -BenchmarkLoggers/std-json-4 393322 2909 ns/op 248 B/op 4 allocs/op -``` \ No newline at end of file +## Credit + +This is a forked and heavily modified variant of github.com/phsym/console-slog. \ No newline at end of file diff --git a/bench_test.go b/bench_test.go index 88736ac..e6f88cd 100644 --- a/bench_test.go +++ b/bench_test.go @@ -22,7 +22,11 @@ var handlers = []struct { }{ {"dummy", &DummyHandler{}}, {"console", NewHandler(io.Discard, &HandlerOptions{Level: slog.LevelDebug, AddSource: false})}, + {"console-headers", NewHandler(io.Discard, &HandlerOptions{HeaderFormat: "%t %{%[foo]h > %}%l %m %a", Level: slog.LevelDebug, AddSource: false})}, + {"console-replaceattr", NewHandler(io.Discard, &HandlerOptions{Level: slog.LevelDebug, AddSource: false, ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr { return a }})}, + {"console-headers-replaceattr", NewHandler(io.Discard, &HandlerOptions{HeaderFormat: "%t %{%[foo]h > %} %l %m %a", Level: slog.LevelDebug, AddSource: false, ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr { return a }})}, {"std-text", slog.NewTextHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug, AddSource: false})}, + {"std-text-replaceattr", slog.NewTextHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug, AddSource: false, ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr { return a }})}, {"std-json", slog.NewJSONHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug, AddSource: false})}, } @@ -36,6 +40,7 @@ var attrs = []slog.Attr{ slog.Any("err", errors.New("yo")), slog.Group("empty"), slog.Group("group", slog.String("bar", "baz")), + slog.String("multi", "foo\nbar"), } var attrsAny = func() (a []any) { diff --git a/buffer.go b/buffer.go index ddff9c3..1f12236 100644 --- a/buffer.go +++ b/buffer.go @@ -2,31 +2,20 @@ package console import ( "io" - "slices" "strconv" "time" ) type buffer []byte -func (b *buffer) Grow(n int) { - *b = slices.Grow(*b, n) -} - -func (b *buffer) Bytes() []byte { - return *b -} - func (b *buffer) String() string { return string(*b) } -func (b *buffer) Len() int { - return len(*b) -} - -func (b *buffer) Cap() int { - return cap(*b) +func (b *buffer) Pad(n int, c byte) { + for ; n > 0; n-- { + b.AppendByte(byte(c)) + } } func (b *buffer) WriteTo(dst io.Writer) (int64, error) { @@ -45,22 +34,19 @@ func (b *buffer) WriteTo(dst io.Writer) (int64, error) { return int64(n), nil } -func (b *buffer) Reset() { - *b = (*b)[:0] -} - -func (b *buffer) Clone() buffer { - return append(buffer(nil), *b...) -} - -func (b *buffer) Clip() { - *b = slices.Clip(*b) +func (b *buffer) Write(bt []byte) (int, error) { + *b = append(*b, bt...) + return len(bt), nil } -func (b *buffer) copy(src *buffer) { - if src.Len() > 0 { - b.Append(src.Bytes()) +func (b *buffer) Reset() { + // To reduce peak allocation, return only smaller buffers to the pool. + const maxBufferSize = 16 << 10 + if cap(*b) > maxBufferSize { + *b = (*b)[:0:maxBufferSize] + return } + *b = (*b)[:0] } func (b *buffer) Append(data []byte) { @@ -71,10 +57,6 @@ func (b *buffer) AppendString(s string) { *b = append(*b, s...) } -// func (b *buffer) AppendQuotedString(s string) { -// b.buff = strconv.AppendQuote(b.buff, s) -// } - func (b *buffer) AppendByte(byt byte) { *b = append(*b, byt) } diff --git a/buffer_test.go b/buffer_test.go index 5a4cdde..39170d7 100644 --- a/buffer_test.go +++ b/buffer_test.go @@ -9,16 +9,16 @@ import ( ) func TestBuffer_Append(t *testing.T) { - b := new(buffer) - AssertZero(t, b.Len()) + var b buffer + AssertZero(t, len(b)) b.AppendString("foobar") - AssertEqual(t, 6, b.Len()) + AssertEqual(t, 6, len(b)) b.AppendString("baz") - AssertEqual(t, 9, b.Len()) + AssertEqual(t, 9, len(b)) AssertEqual(t, "foobarbaz", b.String()) b.AppendByte('.') - AssertEqual(t, 10, b.Len()) + AssertEqual(t, 10, len(b)) AssertEqual(t, "foobarbaz.", b.String()) b.AppendBool(true) @@ -36,7 +36,7 @@ func TestBuffer_Append(t *testing.T) { func TestBuffer_WriteTo(t *testing.T) { dest := bytes.Buffer{} - b := new(buffer) + var b buffer n, err := b.WriteTo(&dest) AssertNoError(t, err) AssertZero(t, n) @@ -45,61 +45,23 @@ func TestBuffer_WriteTo(t *testing.T) { AssertEqual(t, len("foobar"), int(n)) AssertNoError(t, err) AssertEqual(t, "foobar", dest.String()) - AssertZero(t, b.Len()) -} - -func TestBuffer_Clone(t *testing.T) { - b := new(buffer) - b.AppendString("foobar") - b2 := b.Clone() - AssertEqual(t, b.String(), b2.String()) - AssertNotEqual(t, &b.Bytes()[0], &b2.Bytes()[0]) -} - -func TestBuffer_Copy(t *testing.T) { - b := new(buffer) - b.AppendString("foobar") - b2 := new(buffer) - b2.copy(b) - AssertEqual(t, b.String(), b2.String()) - AssertNotEqual(t, &b.Bytes()[0], &b2.Bytes()[0]) + AssertZero(t, len(b)) } func TestBuffer_Reset(t *testing.T) { - b := new(buffer) + var b buffer b.AppendString("foobar") AssertEqual(t, "foobar", b.String()) - AssertEqual(t, len("foobar"), b.Len()) - bufCap := b.Cap() + AssertEqual(t, len("foobar"), len(b)) + bufCap := cap(b) b.Reset() - AssertZero(t, b.Len()) - AssertEqual(t, bufCap, b.Cap()) -} - -func TestBuffer_Grow(t *testing.T) { - b := new(buffer) - AssertZero(t, b.Cap()) - b.Grow(12) - AssertGreaterOrEqual(t, 12, b.Cap()) - b.Grow(6) - AssertGreaterOrEqual(t, 12, b.Cap()) - b.Grow(24) - AssertGreaterOrEqual(t, 24, b.Cap()) -} - -func TestBuffer_Clip(t *testing.T) { - b := new(buffer) - b.AppendString("foobar") - b.Grow(12) - AssertGreaterOrEqual(t, 12, b.Cap()) - b.Clip() - AssertEqual(t, "foobar", b.String()) - AssertEqual(t, len("foobar"), b.Cap()) + AssertZero(t, len(b)) + AssertEqual(t, bufCap, cap(b)) } func TestBuffer_WriteTo_Err(t *testing.T) { w := writerFunc(func(b []byte) (int, error) { return 0, errors.New("nope") }) - b := new(buffer) + var b buffer b.AppendString("foobar") _, err := b.WriteTo(w) AssertError(t, err) diff --git a/duration_test.go b/duration_test.go index ee1b5a8..fcdbebe 100644 --- a/duration_test.go +++ b/duration_test.go @@ -2,6 +2,7 @@ package console import ( "bytes" + "slices" "testing" "time" ) @@ -43,8 +44,7 @@ func BenchmarkDuration(b *testing.B) { }) b.Run("append", func(b *testing.B) { - w := new(buffer) - w.Grow(2048) + w := slices.Grow(buffer{}, 2048) b.ResetTimer() for i := 0; i < b.N; i++ { w.AppendDuration(d) diff --git a/encoding.go b/encoding.go index 6088e65..e1b1987 100644 --- a/encoding.go +++ b/encoding.go @@ -1,192 +1,452 @@ package console import ( + "bytes" "fmt" "log/slog" "path/filepath" - "runtime" + "slices" + "strings" + "sync" "time" + + "github.com/ansel1/console-slog/internal" ) +var encoderPool = &sync.Pool{ + New: func() any { + e := new(encoder) + e.groups = make([]string, 0, 10) + e.buf = make(buffer, 0, 1024) + e.attrBuf = make(buffer, 0, 1024) + e.multilineAttrBuf = make(buffer, 0, 1024) + e.headerAttrs = make([]slog.Attr, 0, 5) + return e + }, +} + type encoder struct { - opts HandlerOptions + h *Handler + buf, attrBuf, multilineAttrBuf buffer + groups []string + headerAttrs []slog.Attr } -func (e encoder) NewLine(buf *buffer) { - buf.AppendByte('\n') +func newEncoder(h *Handler) *encoder { + e := encoderPool.Get().(*encoder) + e.h = h + if h.opts.ReplaceAttr != nil { + e.groups = append(e.groups, h.groups...) + } + e.headerAttrs = slices.Grow(e.headerAttrs, len(h.headerFields))[:len(h.headerFields)] + clear(e.headerAttrs) + return e } -func (e encoder) withColor(b *buffer, c ANSIMod, f func()) { - if c == "" || e.opts.NoColor { - f() +func (e *encoder) free() { + if e == nil { return } - b.AppendString(string(c)) - f() - b.AppendString(string(ResetMod)) + e.h = nil + e.buf.Reset() + e.attrBuf.Reset() + e.multilineAttrBuf.Reset() + e.groups = e.groups[:0] + e.headerAttrs = e.headerAttrs[:0] + encoderPool.Put(e) } -func (e encoder) writeColoredTime(w *buffer, t time.Time, format string, c ANSIMod) { - e.withColor(w, c, func() { - w.AppendTime(t, format) - }) -} +func (e *encoder) encodeTimestamp(tt time.Time) { + if tt.IsZero() { + // elide, and skip ReplaceAttr + return + } -func (e encoder) writeColoredString(w *buffer, s string, c ANSIMod) { - e.withColor(w, c, func() { - w.AppendString(s) - }) -} + if e.h.opts.ReplaceAttr != nil { + attr := e.h.opts.ReplaceAttr(nil, slog.Time(slog.TimeKey, tt)) + attr.Value = attr.Value.Resolve() -func (e encoder) writeColoredInt(w *buffer, i int64, c ANSIMod) { - e.withColor(w, c, func() { - w.AppendInt(i) - }) -} + if attr.Value.Equal(slog.Value{}) { + // elide + return + } -func (e encoder) writeColoredUint(w *buffer, i uint64, c ANSIMod) { - e.withColor(w, c, func() { - w.AppendUint(i) - }) -} + if attr.Value.Kind() != slog.KindTime { + // handle all non-time values by printing them like + // an attr value + e.writeColoredValue(&e.buf, attr.Value, e.h.opts.Theme.Timestamp) + return + } -func (e encoder) writeColoredFloat(w *buffer, i float64, c ANSIMod) { - e.withColor(w, c, func() { - w.AppendFloat(i) - }) -} + // most common case + tt = attr.Value.Time() + if tt.IsZero() { + // elide + return + } + } -func (e encoder) writeColoredBool(w *buffer, b bool, c ANSIMod) { - e.withColor(w, c, func() { - w.AppendBool(b) + e.withColor(&e.buf, e.h.opts.Theme.Timestamp, func() { + e.buf.AppendTime(tt, e.h.opts.TimeFormat) }) } -func (e encoder) writeColoredDuration(w *buffer, d time.Duration, c ANSIMod) { - e.withColor(w, c, func() { - w.AppendDuration(d) - }) -} +func (e *encoder) encodeMessage(level slog.Level, msg string) { + style := e.h.opts.Theme.Message + if level < slog.LevelInfo { + style = e.h.opts.Theme.MessageDebug + } + + if e.h.opts.ReplaceAttr != nil { + attr := e.h.opts.ReplaceAttr(nil, slog.String(slog.MessageKey, msg)) + attr.Value = attr.Value.Resolve() + if attr.Value.Equal(slog.Value{}) { + // elide + return + } -func (e encoder) writeTimestamp(buf *buffer, tt time.Time) { - if !tt.IsZero() { - e.writeColoredTime(buf, tt, e.opts.TimeFormat, e.opts.Theme.Timestamp()) - buf.AppendByte(' ') + e.writeColoredValue(&e.buf, attr.Value, style) + return } + + e.writeColoredString(&e.buf, strings.TrimSpace(msg), style) } -func (e encoder) writeSource(buf *buffer, pc uintptr, cwd string) { - frame, _ := runtime.CallersFrames([]uintptr{pc}).Next() - if cwd != "" { - if ff, err := filepath.Rel(cwd, frame.File); err == nil { - frame.File = ff +func (e *encoder) encodeHeader(a slog.Attr, width int, rightAlign bool) { + if a.Value.Equal(slog.Value{}) { + // just pad as needed + if width > 0 { + e.buf.Pad(width, ' ') } + return } - e.withColor(buf, e.opts.Theme.Source(), func() { - buf.AppendString(frame.File) - buf.AppendByte(':') - buf.AppendInt(int64(frame.Line)) + + e.withColor(&e.buf, e.h.opts.Theme.Header, func() { + l := len(e.buf) + e.writeValue(&e.buf, a.Value) + if width <= 0 { + return + } + // truncate or pad to required width + remainingWidth := l + width - len(e.buf) + if remainingWidth < 0 { + // truncate + e.buf = e.buf[:l+width] + } else if remainingWidth > 0 { + if rightAlign { + // For right alignment, shift the text right in-place: + // 1. Get the text length + textLen := len(e.buf) - l + // 2. Add padding to reach final width + e.buf.Pad(remainingWidth, ' ') + // 3. Move the text to the right by copying from end to start + for i := 0; i < textLen; i++ { + e.buf[len(e.buf)-1-i] = e.buf[l+textLen-1-i] + } + // 4. Fill the left side with spaces + for i := 0; i < remainingWidth; i++ { + e.buf[l+i] = ' ' + } + } else { + // Left align - just pad with spaces + e.buf.Pad(remainingWidth, ' ') + } + } }) - e.writeColoredString(buf, " > ", e.opts.Theme.AttrKey()) } -func (e encoder) writeMessage(buf *buffer, level slog.Level, msg string) { - if level >= slog.LevelInfo { - e.writeColoredString(buf, msg, e.opts.Theme.Message()) +func (e *encoder) encodeLevel(l slog.Level, abbreviated bool) { + var val slog.Value + var writeVal bool + + if e.h.opts.ReplaceAttr != nil { + attr := e.h.opts.ReplaceAttr(nil, slog.Any(slog.LevelKey, l)) + attr.Value = attr.Value.Resolve() + + if attr.Value.Equal(slog.Value{}) { + // elide + return + } + + val = attr.Value + writeVal = true + + if val.Kind() == slog.KindAny { + if ll, ok := val.Any().(slog.Level); ok { + // generally, we'll write the returned value, except in one + // case: when the resolved value is itself a slog.Level + l = ll + writeVal = false + } + } + } + + var style ANSIMod + var str string + var delta int + switch { + case l >= slog.LevelError: + style = e.h.opts.Theme.LevelError + str = "ERR" + if !abbreviated { + str = "ERROR" + } + delta = int(l - slog.LevelError) + case l >= slog.LevelWarn: + style = e.h.opts.Theme.LevelWarn + str = "WRN" + if !abbreviated { + str = "WARN" + } + delta = int(l - slog.LevelWarn) + case l >= slog.LevelInfo: + style = e.h.opts.Theme.LevelInfo + str = "INF" + if !abbreviated { + str = "INFO" + } + delta = int(l - slog.LevelInfo) + case l >= slog.LevelDebug: + style = e.h.opts.Theme.LevelDebug + str = "DBG" + if !abbreviated { + str = "DEBUG" + } + delta = int(l - slog.LevelDebug) + default: + style = e.h.opts.Theme.LevelDebug + str = "DBG" + if !abbreviated { + str = "DEBUG" + } + delta = int(l - slog.LevelDebug) + } + if writeVal { + e.writeColoredValue(&e.buf, val, style) } else { - e.writeColoredString(buf, msg, e.opts.Theme.MessageDebug()) + if delta != 0 { + str = fmt.Sprintf("%s%+d", str, delta) + } + e.writeColoredString(&e.buf, str, style) + } +} + +func (e *encoder) encodeSource(src slog.Source) { + if src.File == "" && src.Line == 0 { + // elide empty source + return + } + + v := slog.AnyValue(&src) + + if e.h.opts.ReplaceAttr != nil { + attr := e.h.opts.ReplaceAttr(nil, slog.Attr{Key: slog.SourceKey, Value: v}) + attr.Value = attr.Value.Resolve() + + if attr.Value.Equal(slog.Value{}) { + // elide + return + } + v = attr.Value } + // Use source style for the value + e.writeColoredValue(&e.buf, v, e.h.opts.Theme.Source) } -func (e encoder) writeAttr(buf *buffer, a slog.Attr, group string) { +func (e *encoder) encodeAttr(groupPrefix string, a slog.Attr) { + + a.Value = a.Value.Resolve() + if a.Value.Kind() != slog.KindGroup && e.h.opts.ReplaceAttr != nil { + a = e.h.opts.ReplaceAttr(e.groups, a) + a.Value = a.Value.Resolve() + } // Elide empty Attrs. if a.Equal(slog.Attr{}) { return } - value := a.Value.Resolve() + + value := a.Value + if value.Kind() == slog.KindGroup { subgroup := a.Key - if group != "" { - subgroup = group + "." + a.Key + if groupPrefix != "" { + subgroup = groupPrefix + "." + a.Key + } + if e.h.opts.ReplaceAttr != nil { + e.groups = append(e.groups, a.Key) } for _, attr := range value.Group() { - e.writeAttr(buf, attr, subgroup) + e.encodeAttr(subgroup, attr) + } + if e.h.opts.ReplaceAttr != nil { + e.groups = e.groups[:len(e.groups)-1] } return } - buf.AppendByte(' ') - e.withColor(buf, e.opts.Theme.AttrKey(), func() { + + for i, f := range e.h.headerFields { + if f.key == a.Key && f.groupPrefix == groupPrefix { + e.headerAttrs[i] = a + return + } + } + + offset := len(e.attrBuf) + valOffset := e.writeAttr(a, groupPrefix) + + // check if the last attr written has newlines in it + // if so, move it to the trailerBuf + if bytes.IndexByte(e.attrBuf[offset:], '\n') >= 0 { + if internal.FeatureFlagNewMultilineAttrs { + val := e.attrBuf[valOffset:] + e.writeMultilineAttr(a.Key, groupPrefix, val) + } else { + e.multilineAttrBuf.Append(e.attrBuf[offset:]) + } + + // rewind the middle buffer + e.attrBuf = e.attrBuf[:offset] + } +} + +func (e *encoder) withColor(b *buffer, c ANSIMod, f func()) { + if c == "" || e.h.opts.NoColor { + f() + return + } + b.AppendString(string(c)) + f() + b.AppendString(string(ResetMod)) +} + +func (e *encoder) writeColoredString(w *buffer, s string, c ANSIMod) { + e.withColor(w, c, func() { + w.AppendString(s) + }) +} + +// writeAttr encodes the attr to the attrBuf. The group will be prepended +// to the key, joined with a '.' +// +// returns the offset where the value starts, which may be used by the +// caller to split the key and value +func (e *encoder) writeAttr(a slog.Attr, group string) int { + value := a.Value + + e.attrBuf.AppendByte(' ') + e.withColor(&e.attrBuf, e.h.opts.Theme.AttrKey, func() { + if group != "" { + e.attrBuf.AppendString(group) + e.attrBuf.AppendByte('.') + } + e.attrBuf.AppendString(a.Key) + e.attrBuf.AppendByte('=') + }) + + style := e.h.opts.Theme.AttrValue + if value.Kind() == slog.KindAny { + if _, ok := value.Any().(error); ok { + style = e.h.opts.Theme.AttrValueError + } + } + valOffset := len(e.attrBuf) + e.writeColoredValue(&e.attrBuf, value, style) + return valOffset +} + +func (e *encoder) writeMultilineAttr(key, group string, value []byte) { + e.multilineAttrBuf.AppendByte('\n') + e.withColor(&e.multilineAttrBuf, e.h.opts.Theme.AttrKey, func() { + e.multilineAttrBuf.AppendString("=== ") if group != "" { - buf.AppendString(group) - buf.AppendByte('.') + e.multilineAttrBuf.AppendString(group) + e.multilineAttrBuf.AppendByte('.') } - buf.AppendString(a.Key) - buf.AppendByte('=') + e.multilineAttrBuf.AppendString(key) + e.multilineAttrBuf.AppendString(" ===\n") }) - e.writeValue(buf, value) + e.multilineAttrBuf.Append(value) } -func (e encoder) writeValue(buf *buffer, value slog.Value) { - attrValue := e.opts.Theme.AttrValue() +func (e *encoder) writeValue(buf *buffer, value slog.Value) { switch value.Kind() { case slog.KindInt64: - e.writeColoredInt(buf, value.Int64(), attrValue) + buf.AppendInt(value.Int64()) case slog.KindBool: - e.writeColoredBool(buf, value.Bool(), attrValue) + buf.AppendBool(value.Bool()) case slog.KindFloat64: - e.writeColoredFloat(buf, value.Float64(), attrValue) + buf.AppendFloat(value.Float64()) case slog.KindTime: - e.writeColoredTime(buf, value.Time(), e.opts.TimeFormat, attrValue) + buf.AppendTime(value.Time(), e.h.opts.TimeFormat) case slog.KindUint64: - e.writeColoredUint(buf, value.Uint64(), attrValue) + buf.AppendUint(value.Uint64()) case slog.KindDuration: - e.writeColoredDuration(buf, value.Duration(), attrValue) + buf.AppendDuration(value.Duration()) case slog.KindAny: switch v := value.Any().(type) { case error: - e.writeColoredString(buf, v.Error(), e.opts.Theme.AttrValueError()) + if _, ok := v.(fmt.Formatter); ok { + fmt.Fprintf(buf, "%+v", v) + } else { + buf.AppendString(v.Error()) + } return case fmt.Stringer: - e.writeColoredString(buf, v.String(), attrValue) + buf.AppendString(v.String()) + return + case *slog.Source: + buf.AppendString(trimmedPath(v.File, cwd, e.h.opts.TruncateSourcePath)) + buf.AppendByte(':') + buf.AppendInt(int64(v.Line)) return } fallthrough case slog.KindString: fallthrough default: - e.writeColoredString(buf, value.String(), attrValue) + buf.AppendString(value.String()) } } -func (e encoder) writeLevel(buf *buffer, l slog.Level) { - var style ANSIMod - var str string - var delta int - switch { - case l >= slog.LevelError: - style = e.opts.Theme.LevelError() - str = "ERR" - delta = int(l - slog.LevelError) - case l >= slog.LevelWarn: - style = e.opts.Theme.LevelWarn() - str = "WRN" - delta = int(l - slog.LevelWarn) - case l >= slog.LevelInfo: - style = e.opts.Theme.LevelInfo() - str = "INF" - delta = int(l - slog.LevelInfo) - case l >= slog.LevelDebug: - style = e.opts.Theme.LevelDebug() - str = "DBG" - delta = int(l - slog.LevelDebug) - default: - style = e.opts.Theme.LevelDebug() - str = "DBG" - delta = int(l - slog.LevelDebug) +func (e *encoder) writeColoredValue(buf *buffer, value slog.Value, style ANSIMod) { + e.withColor(buf, style, func() { + e.writeValue(buf, value) + }) +} + +func trimmedPath(path string, cwd string, truncate int) string { + // if the file path appears to be under the current + // working directory, then we're probably running + // in a dev environment, and we can show the + // path of the source file relative to the + // working directory + if cwd != "" && strings.HasPrefix(path, cwd) { + if ff, err := filepath.Rel(cwd, path); err == nil { + path = ff + } } - if delta != 0 { - str = fmt.Sprintf("%s%+d", str, delta) + + // Otherwise, show the full file path. + // If truncate is > 0, then truncate to that last + // number of path segments. + // 1 = just the filename + // 2 = the filename and its parent dir + // 3 = the filename and its two parent dirs + // ...etc + // + // Note that the go compiler always uses forward + // slashes, even if the compiler was run on Windows. + // + // See https://github.com/golang/go/issues/3335 + // and https://github.com/golang/go/issues/18151 + + var start int + for idx := len(path); truncate > 0; truncate-- { + idx = strings.LastIndexByte(path[:idx], '/') + if idx == -1 { + break + } + start = idx + 1 } - e.writeColoredString(buf, str, style) - buf.AppendByte(' ') + return path[start:] } diff --git a/example/main.go b/example/main.go index ca78958..4423b73 100644 --- a/example/main.go +++ b/example/main.go @@ -5,12 +5,17 @@ import ( "log/slog" "os" - "github.com/phsym/console-slog" + "github.com/ansel1/console-slog" ) func main() { logger := slog.New( - console.NewHandler(os.Stderr, &console.HandlerOptions{Level: slog.LevelDebug, AddSource: true}), + console.NewHandler(os.Stderr, &console.HandlerOptions{ + Level: slog.LevelDebug, + AddSource: true, + TruncateSourcePath: 2, + TimeFormat: "15:04:05.000", + }), ) slog.SetDefault(logger) slog.Info("Hello world!", "foo", "bar") @@ -20,7 +25,7 @@ func main() { logger = logger.With("foo", "bar"). WithGroup("the-group"). - With("bar", "baz") + With("bar", "baz", "logger", "main") - logger.Info("group info", "attr", "value") + logger.Info("group info", "multiline", "hello\nworld", "attr", "value") } diff --git a/go.mod b/go.mod index a29d282..5fcafd2 100644 --- a/go.mod +++ b/go.mod @@ -1,3 +1,3 @@ -module github.com/phsym/console-slog +module github.com/ansel1/console-slog go 1.21 diff --git a/handler.go b/handler.go index 82ce3ea..d7e5c36 100644 --- a/handler.go +++ b/handler.go @@ -1,23 +1,37 @@ package console import ( + "bytes" "context" + "fmt" "io" "log/slog" "os" + "runtime" + "slices" "strings" "sync" "time" + + "github.com/ansel1/console-slog/internal" ) -var bufferPool = &sync.Pool{ - New: func() any { return new(buffer) }, -} +var cwd string -var cwd, _ = os.Getwd() +func init() { + cwd, _ = os.Getwd() + // We compare cwd to the filepath in runtime.Frame.File + // It turns out, an old legacy behavior of go is that runtime.Frame.File + // will always contain file paths with forward slashes, even if compiled + // on Windows. + // See https://github.com/golang/go/issues/3335 + // and https://github.com/golang/go/issues/18151 + cwd = strings.ReplaceAll(cwd, "\\", "/") +} // HandlerOptions are options for a ConsoleHandler. // A zero HandlerOptions consists entirely of default values. +// ReplaceAttr works identically to [slog.HandlerOptions.ReplaceAttr] type HandlerOptions struct { // AddSource causes the handler to compute the source code position // of the log statement and add a SourceKey attribute to the output. @@ -38,16 +52,123 @@ type HandlerOptions struct { // Theme defines the colorized output using ANSI escape sequences Theme Theme + + // ReplaceAttr is called to rewrite each non-group attribute before it is logged. + // See [slog.HandlerOptions] + ReplaceAttr func(groups []string, a slog.Attr) slog.Attr + + // TruncateSourcePath shortens the source file path, if AddSource=true. + // If 0, no truncation is done. + // If >0, the file path is truncated to that many trailing path segments. + // For example: + // + // users.go:34 // TruncateSourcePath = 1 + // models/users.go:34 // TruncateSourcePath = 2 + // ...etc + TruncateSourcePath int + + // HeaderFormat specifies the format of the log header. + // + // The default format is "%t %l %[source]h > %m". + // + // The format is a string containing verbs, which are expanded as follows: + // + // %t timestamp + // %l abbreviated level (e.g. "INF") + // %L level (e.g. "INFO") + // %m message + // %s source (if omitted, source is just handled as an attribute) + // %a attributes + // %[key]h header with the given key. + // %{ group open + // %(style){ group open with style - applies the specified Theme style to any strings in the group + // %} group close + // + // Headers print the value of the attribute with the given key, and remove that + // attribute from the end of the log line. + // + // Headers can be customized with width and alignment modifiers, + // similar to fmt.Printf verbs. For example: + // + // %[key]10h // left-aligned, width 10 + // %[key]-10h // right-aligned, width 10 + // + // Groups will omit their contents if all the fields in that group are omitted. For example: + // + // "%l %{%[logger]h %[source]h > %} %m" + // + // will print "INF main main.go:123 > msg" if the either the logger or source attribute is present. But if the + // both attributes are not present, or were elided by ReplaceAttr, then this will print "INF msg". Groups can + // be nested. + // + // Groups can also be styled using the Theme styles by specifying a style in parentheses after the percent sign: + // + // "%l %(source){ %[logger]h %} %m" + // + // will apply the source style from the Theme to the fixed strings in the group. By default, the Header style is used. + // + // Whitespace is generally merged to leave a single space between fields. Leading and trailing whitespace is trimmed. + // + // Examples: + // + // "%t %l %m" // timestamp, level, message + // "%t [%l] %m" // timestamp, level in brackets, message + // "%t %l:%m" // timestamp, level:message + // "%t %l %[key]h %m" // timestamp, level, header with key "key", message + // "%t %l %[key1]h %[key2]h %m" // timestamp, level, header with key "key1", header with key "key2", message + // "%t %l %[key]10h %m" // timestamp, level, header with key "key" and width 10, message + // "%t %l %[key]-10h %m" // timestamp, level, right-aligned header with key "key" and width 10, message + // "%t %l %L %m" // timestamp, abbreviated level, non-abbreviated level, message + // "%t %l %L- %m" // timestamp, abbreviated level, right-aligned non-abbreviated level, message + // "%t %l %m string literal" // timestamp, level, message, and then " string literal" + // "prefix %t %l %m suffix" // "prefix ", timestamp, level, message, and then " suffix" + // "%% %t %l %m" // literal "%", timestamp, level, message + // "%{[%t]%} %{[%l]%} %m" // timestamp and level in brackets, message, brackets will be omitted if empty + HeaderFormat string } +const defaultHeaderFormat = "%t %l %{%s >%} %m %a" + type Handler struct { - opts HandlerOptions - out io.Writer - group string - context buffer - enc *encoder + opts HandlerOptions + out io.Writer + groupPrefix string + groups []string + context, multilineContext buffer + fields []any + headerFields []headerField + sourceAsAttr bool + mu *sync.Mutex +} + +type timestampField struct{} + +type headerField struct { + groupPrefix string + key string + width int + rightAlign bool + memo string } +type levelField struct { + abbreviated bool +} +type messageField struct{} + +type attrsField struct{} + +type groupOpen struct { + style string +} +type groupClose struct{} + +type spacer struct { + hard bool +} + +type sourceField struct{} + var _ slog.Handler = (*Handler)(nil) // NewHandler creates a Handler that writes to w, @@ -63,15 +184,63 @@ func NewHandler(out io.Writer, opts *HandlerOptions) *Handler { if opts.TimeFormat == "" { opts.TimeFormat = time.DateTime } - if opts.Theme == nil { + if opts.Theme.Name == "" { opts.Theme = NewDefaultTheme() } + if opts.HeaderFormat == "" { + opts.HeaderFormat = defaultHeaderFormat // default format + } + + fields, headerFields := parseFormat(opts.HeaderFormat, opts.Theme) + + // find spocerFields adjacent to string fields and mark them + // as hard spaces. hard spaces should not be skipped, only + // coalesced + var wasString bool + lastSpace := -1 + for i, f := range fields { + switch f.(type) { + case headerField, levelField, messageField, timestampField: + wasString = false + lastSpace = -1 + case string: + if lastSpace != -1 { + // string immediately followed space, so the + // space is hard. + fields[lastSpace] = spacer{hard: true} + } + wasString = true + lastSpace = -1 + case spacer: + if wasString { + // space immedately followed a string, so the space + // is hard + fields[i] = spacer{hard: true} + } + lastSpace = i + wasString = false + } + } + + // Check if the parsed fields include any sourceField instances + // If not, set sourceAsAttr to true so source is handled as a regular attribute + sourceAsAttr := true + for _, f := range fields { + if _, ok := f.(sourceField); ok { + sourceAsAttr = false + break + } + } + return &Handler{ - opts: *opts, // Copy struct - out: out, - group: "", - context: nil, - enc: &encoder{opts: *opts}, + opts: *opts, // Copy struct + out: out, + groupPrefix: "", + context: nil, + fields: fields, + headerFields: headerFields, + sourceAsAttr: sourceAsAttr, + mu: &sync.Mutex{}, } } @@ -80,58 +249,504 @@ func (h *Handler) Enabled(_ context.Context, l slog.Level) bool { return l >= h.opts.Level.Level() } -// Handle implements slog.Handler. -func (h *Handler) Handle(_ context.Context, rec slog.Record) error { - buf := bufferPool.Get().(*buffer) +func (h *Handler) Handle(ctx context.Context, rec slog.Record) error { + enc := newEncoder(h) + + var src slog.Source - h.enc.writeTimestamp(buf, rec.Time) - h.enc.writeLevel(buf, rec.Level) if h.opts.AddSource && rec.PC > 0 { - h.enc.writeSource(buf, rec.PC, cwd) + frame, _ := runtime.CallersFrames([]uintptr{rec.PC}).Next() + src.Function = frame.Function + src.File = frame.File + src.Line = frame.Line + + if h.sourceAsAttr { + // the source attr should not be inside any open groups + groups := enc.groups + enc.groups = nil + enc.encodeAttr("", slog.Any(slog.SourceKey, &src)) + enc.groups = groups + } } - h.enc.writeMessage(buf, rec.Level, rec.Message) - buf.copy(&h.context) + + enc.attrBuf.Append(h.context) + enc.multilineAttrBuf.Append(h.multilineContext) + rec.Attrs(func(a slog.Attr) bool { - h.enc.writeAttr(buf, a, h.group) + enc.encodeAttr(h.groupPrefix, a) return true }) - h.enc.NewLine(buf) - if _, err := buf.WriteTo(h.out); err != nil { - buf.Reset() - bufferPool.Put(buf) + + headerIdx := 0 + var state encodeState + // use a fixed size stack to avoid allocations, 3 deep nested groups should be enough for most cases + stackArr := [3]encodeState{} + stack := stackArr[:0] + var attrsFieldSeen bool + for _, f := range h.fields { + switch f := f.(type) { + case groupOpen: + stack = append(stack, state) + state.groupStart = len(enc.buf) + state.printedField = false + state.seenFields = 0 + // Store the style to use for this group + state.style = f.style + continue + case groupClose: + if len(stack) == 0 { + // missing group open + // no-op + continue + } + + if state.printedField || state.seenFields == 0 { + // merge the current state with the prior state + lastState := stack[len(stack)-1] + state.groupStart = lastState.groupStart + state.style = lastState.style + state.seenFields += lastState.seenFields + } else { + // no fields were printed in this group, so + // rollback the entire group and pop back to + // the outer state + enc.buf = enc.buf[:state.groupStart] + state = stack[len(stack)-1] + } + // pop a state off the stack + stack = stack[:len(stack)-1] + continue + case spacer: + if len(enc.buf) == 0 { + // special case, always skip leading space + continue + } + + if f.hard { + state.pendingHardSpace = true + } else { + // only queue a soft space if the last + // thing printed was not a string field. + state.pendingSpace = state.anchored + } + + continue + case string: + if state.pendingHardSpace { + enc.buf.AppendByte(' ') + } + state.pendingHardSpace = false + state.pendingSpace = false + state.anchored = false + + // Use the style specified for the group if available + style, _ := getThemeStyleByName(h.opts.Theme, state.style) + enc.withColor(&enc.buf, style, func() { + enc.buf.AppendString(f) + }) + continue + } + if state.pendingSpace || state.pendingHardSpace { + enc.buf.AppendByte(' ') + } + l := len(enc.buf) + state.seenFields++ + switch f := f.(type) { + case headerField: + hf := h.headerFields[headerIdx] + if enc.headerAttrs[headerIdx].Equal(slog.Attr{}) && hf.memo != "" { + enc.buf.AppendString(hf.memo) + } else { + enc.encodeHeader(enc.headerAttrs[headerIdx], hf.width, hf.rightAlign) + } + headerIdx++ + + case levelField: + enc.encodeLevel(rec.Level, f.abbreviated) + case messageField: + enc.encodeMessage(rec.Level, rec.Message) + case attrsField: + // trim the attrBuf and multilineAttrBuf to remove leading spaces + // but leave a space between attrBuf and multilineAttrBuf + if len(enc.attrBuf) > 0 { + enc.attrBuf = bytes.TrimSpace(enc.attrBuf) + } else if len(enc.multilineAttrBuf) > 0 && !internal.FeatureFlagNewMultilineAttrs { + enc.multilineAttrBuf = bytes.TrimSpace(enc.multilineAttrBuf) + } + attrsFieldSeen = true + enc.buf.Append(enc.attrBuf) + if !internal.FeatureFlagNewMultilineAttrs { + enc.buf.Append(enc.multilineAttrBuf) + } + case sourceField: + enc.encodeSource(src) + case timestampField: + enc.encodeTimestamp(rec.Time) + } + printed := len(enc.buf) > l + state.printedField = state.printedField || printed + if printed { + state.pendingSpace = false + state.pendingHardSpace = false + state.anchored = true + } else if state.pendingSpace || state.pendingHardSpace { + // chop the last space + enc.buf = bytes.TrimSpace(enc.buf) + // leave state.spacePending as is for next + // field to handle + } + } + + if internal.FeatureFlagNewMultilineAttrs && attrsFieldSeen && len(enc.multilineAttrBuf) > 0 { + enc.buf.Append(enc.multilineAttrBuf) + } + + enc.buf.AppendByte('\n') + + h.mu.Lock() + defer h.mu.Unlock() + if _, err := enc.buf.WriteTo(h.out); err != nil { return err } - bufferPool.Put(buf) + + enc.free() return nil } +type encodeState struct { + // index in buffer of where the currently open group started. + // if group ends up being elided, buffer will rollback to this + // index + groupStart int + // whether any field in this group has not been elided. When a group + // closes, if this is false, the entire group will be elided + printedField bool + // number of fields seen in this group. If this is 0, then + // the group only contains fixed strings, and no fields, adn + // should not be elided. + seenFields int + + anchored, pendingSpace, pendingHardSpace bool + style string +} + // WithAttrs implements slog.Handler. func (h *Handler) WithAttrs(attrs []slog.Attr) slog.Handler { - newCtx := h.context + enc := newEncoder(h) + for _, a := range attrs { - h.enc.writeAttr(&newCtx, a, h.group) + enc.encodeAttr(h.groupPrefix, a) + } + + headerFields := memoizeHeaders(enc, h.headerFields) + + newCtx := h.context + newMultiCtx := h.multilineContext + if len(enc.attrBuf) > 0 { + newCtx = append(newCtx, enc.attrBuf...) + newCtx = slices.Clip(newCtx) + } + if len(enc.multilineAttrBuf) > 0 { + newMultiCtx = append(newMultiCtx, enc.multilineAttrBuf...) + newMultiCtx = slices.Clip(newMultiCtx) } - newCtx.Clip() + + enc.free() + return &Handler{ - opts: h.opts, - out: h.out, - group: h.group, - context: newCtx, - enc: h.enc, + opts: h.opts, + out: h.out, + groupPrefix: h.groupPrefix, + context: newCtx, + multilineContext: newMultiCtx, + groups: h.groups, + fields: h.fields, + headerFields: headerFields, + sourceAsAttr: h.sourceAsAttr, + mu: h.mu, } } // WithGroup implements slog.Handler. func (h *Handler) WithGroup(name string) slog.Handler { name = strings.TrimSpace(name) - if h.group != "" { - name = h.group + "." + name + groupPrefix := name + if h.groupPrefix != "" { + groupPrefix = h.groupPrefix + "." + name } return &Handler{ - opts: h.opts, - out: h.out, - group: name, - context: h.context, - enc: h.enc, + opts: h.opts, + out: h.out, + groupPrefix: groupPrefix, + context: h.context, + groups: append(h.groups, name), + fields: h.fields, + headerFields: h.headerFields, + sourceAsAttr: h.sourceAsAttr, + mu: h.mu, + } +} + +func memoizeHeaders(enc *encoder, headerFields []headerField) []headerField { + newFields := make([]headerField, len(headerFields)) + copy(newFields, headerFields) + + for i := range newFields { + if !enc.headerAttrs[i].Equal(slog.Attr{}) { + enc.buf.Reset() + enc.encodeHeader(enc.headerAttrs[i], newFields[i].width, newFields[i].rightAlign) + newFields[i].memo = enc.buf.String() + } + } + return newFields +} + +// parseFormat parses a format string into a list of fields and the number of headerFields. +// +// Supported format verbs: +// +// %t - timestampField +// %h - headerField, requires the [name] modifier. +// Supports width, right-alignment (-) modifiers. +// %m - messageField +// %l - abbreviated levelField: The log level in abbreviated form (e.g., "INF"). +// %L - non-abbreviated levelField: The log level in full form (e.g., "INFO"). +// %{ - groupOpen +// %} - groupClose +// %s - sourceField +// +// Modifiers: +// +// [name] (for %h): The key of the attribute to capture as a header. This modifier is required for the %h verb. +// width (for %h): An integer specifying the fixed width of the header. This modifier is optional. +// - (for %h): Indicates right-alignment of the header. This modifier is optional. +// +// Examples: +// +// "%t %l %m" // timestamp, level, message +// "%t [%l] %m" // timestamp, level in brackets, message +// "%t %l:%m" // timestamp, level:message +// "%t %l %[key]h %m" // timestamp, level, header with key "key", message +// "%t %l %[key1]h %[key2]h %m" // timestamp, level, header with key "key1", header with key "key2", message +// "%t %l %[key]10h %m" // timestamp, level, header with key "key" and width 10, message +// "%t %l %[key]-10h %m" // timestamp, level, right-aligned header with key "key" and width 10, message +// "%t %l %L %m" // timestamp, abbreviated level, non-abbreviated level, message +// "%t %l %L- %m" // timestamp, abbreviated level, right-aligned non-abbreviated level, message +// "%t %l %m string literal" // timestamp, level, message, and then " string literal" +// "prefix %t %l %m suffix" // "prefix ", timestamp, level, message, and then " suffix" +// "%% %t %l %m" // literal "%", timestamp, level, message +// "%t %l %s" // timestamp, level, source location (e.g., "file.go:123 functionName") +// "%t %l %m %(source){→ %s%}" // timestamp, level, message, and then source wrapped in a group with a custom string. +// // The string in the group will use the "source" style, and the group will be omitted if the source attribute is not present +func parseFormat(format string, theme Theme) (fields []any, headerFields []headerField) { + fields = make([]any, 0) + headerFields = make([]headerField, 0) + + format = strings.TrimSpace(format) + lastWasSpace := false + + for i := 0; i < len(format); i++ { + if format[i] == ' ' { + if !lastWasSpace { + fields = append(fields, spacer{}) + lastWasSpace = true + } + continue + } + lastWasSpace = false + + if format[i] != '%' { + // Find the next % or space or end of string + start := i + for i < len(format) && format[i] != '%' && format[i] != ' ' { + i++ + } + fields = append(fields, format[start:i]) + i-- // compensate for loop increment + continue + } + + // Handle %% escape + if i+1 < len(format) && format[i+1] == '%' { + fields = append(fields, "%") + i++ + continue + } + + // Parse format verb and any modifiers + i++ + if i >= len(format) { + fields = append(fields, "%!(MISSING_VERB)") + break + } + + // Check for modifiers before verb + var width int + var rightAlign bool + var key string + var style string + var styleSeen, keySeen, widthSeen bool + + // Look for (style) modifier for groupOpen + if format[i] == '(' { + styleSeen = true + // Find the next ) or end of string + end := i + 1 + for end < len(format) && format[end] != ')' && format[end] != ' ' { + end++ + } + if end >= len(format) || format[end] != ')' { + fields = append(fields, fmt.Sprintf("%%!%s(MISSING_CLOSING_PARENTHESIS)", format[i:end])) + i = end - 1 // Position just before the next character to process + continue + } + style = format[i+1 : end] + i = end + 1 + } + + // Look for [name] modifier + if format[i] == '[' { + keySeen = true + // Find the next ] or end of string + end := i + 1 + for end < len(format) && format[end] != ']' && format[end] != ' ' { + end++ + } + if end >= len(format) || format[end] != ']' { + fields = append(fields, fmt.Sprintf("%%!%s(MISSING_CLOSING_BRACKET)", format[i:end])) + i = end - 1 // Position just before the next character to process + continue + } + key = format[i+1 : end] + i = end + 1 + } + + // Look for modifiers + for i < len(format) { + if format[i] == '-' { + rightAlign = true + i++ + } else if format[i] >= '0' && format[i] <= '9' { + widthSeen = true + width = 0 + for i < len(format) && format[i] >= '0' && format[i] <= '9' { + width = width*10 + int(format[i]-'0') + i++ + } + } else { + break + } + } + + if i >= len(format) { + fields = append(fields, "%!(MISSING_VERB)") + break + } + + var field any + + // Parse the verb + switch format[i] { + case ' ': + fields = append(fields, "%!(MISSING_VERB)") + // backtrack so the space is included in the next field + i-- + continue + case 't': + field = timestampField{} + case 'h': + if key == "" { + fields = append(fields, "%!h(MISSING_HEADER_NAME)") + continue + } + hf := headerField{ + key: key, + width: width, + rightAlign: rightAlign, + } + if idx := strings.LastIndexByte(key, '.'); idx > -1 { + hf.groupPrefix = key[:idx] + hf.key = key[idx+1:] + } + field = hf + case 'm': + field = messageField{} + case 'l': + field = levelField{abbreviated: true} + case 'L': + field = levelField{abbreviated: false} + case '{': + if _, ok := getThemeStyleByName(theme, style); !ok { + fields = append(fields, fmt.Sprintf("%%!{(%s)(INVALID_STYLE_MODIFIER)", style)) + continue + } + field = groupOpen{style: style} + case '}': + field = groupClose{} + case 's': + field = sourceField{} + case 'a': + field = attrsField{} + default: + fields = append(fields, fmt.Sprintf("%%!%c(INVALID_VERB)", format[i])) + continue + } + + // Check for invalid combinations + switch { + case styleSeen && format[i] != '{': + fields = append(fields, fmt.Sprintf("%%!((INVALID_MODIFIER)%c", format[i])) + continue + case keySeen && format[i] != 'h': + fields = append(fields, fmt.Sprintf("%%![(INVALID_MODIFIER)%c", format[i])) + continue + case widthSeen && format[i] != 'h': + fields = append(fields, fmt.Sprintf("%%!%d(INVALID_MODIFIER)%c", width, format[i])) + continue + case rightAlign && format[i] != 'h': + fields = append(fields, fmt.Sprintf("%%!-(INVALID_MODIFIER)%c", format[i])) + continue + } + + fields = append(fields, field) + if _, ok := field.(headerField); ok { + headerFields = append(headerFields, field.(headerField)) + } + } + + return fields, headerFields +} + +// Helper function to get style from theme by name +func getThemeStyleByName(theme Theme, name string) (ANSIMod, bool) { + switch name { + case "": + return theme.Header, true + case "timestamp": + return theme.Timestamp, true + case "header": + return theme.Header, true + case "source": + return theme.Source, true + case "message": + return theme.Message, true + case "messageDebug": + return theme.MessageDebug, true + case "attrKey": + return theme.AttrKey, true + case "attrValue": + return theme.AttrValue, true + case "attrValueError": + return theme.AttrValueError, true + case "levelError": + return theme.LevelError, true + case "levelWarn": + return theme.LevelWarn, true + case "levelInfo": + return theme.LevelInfo, true + case "levelDebug": + return theme.LevelDebug, true + default: + return theme.Header, false // Default to header style, but indicate style was not recognized } } diff --git a/handler_test.go b/handler_test.go index eb09629..f167ba5 100644 --- a/handler_test.go +++ b/handler_test.go @@ -5,49 +5,113 @@ import ( "context" "errors" "fmt" + "io" "log/slog" "os" "path/filepath" + "reflect" "runtime" + "strings" "testing" "time" + + "github.com/ansel1/console-slog/internal" ) +func TestNewHandler(t *testing.T) { + h := NewHandler(nil, nil) + AssertEqual(t, time.DateTime, h.opts.TimeFormat) + AssertEqual(t, NewDefaultTheme().Name, h.opts.Theme.Name) + AssertEqual(t, defaultHeaderFormat, h.opts.HeaderFormat) +} + +func TestHandler_Enabled(t *testing.T) { + tests := []slog.Level{ + slog.LevelDebug - 1, slog.LevelDebug, slog.LevelInfo, slog.LevelWarn, slog.LevelError, slog.LevelError + 1, + } + + for _, lvl := range tests { + t.Run(lvl.String(), func(t *testing.T) { + h := NewHandler(io.Discard, &HandlerOptions{Level: lvl}) + if h.Enabled(context.Background(), lvl-1) { + t.Errorf("Expected %v to be disabled, got: enabled", lvl-1) + } + if !h.Enabled(context.Background(), lvl) { + t.Errorf("Expected %v to be enabled, got: disabled", lvl) + } + if !h.Enabled(context.Background(), lvl+1) { + t.Errorf("Expected %v to be enabled, got: disabled", lvl+1) + } + }) + } +} + func TestHandler_TimeFormat(t *testing.T) { - buf := bytes.Buffer{} - h := NewHandler(&buf, &HandlerOptions{TimeFormat: time.RFC3339Nano, NoColor: true}) - now := time.Now() - rec := slog.NewRecord(now, slog.LevelInfo, "foobar", 0) - endTime := now.Add(time.Second) - rec.AddAttrs(slog.Time("endtime", endTime)) - AssertNoError(t, h.Handle(context.Background(), rec)) - - expected := fmt.Sprintf("%s INF foobar endtime=%s\n", now.Format(time.RFC3339Nano), endTime.Format(time.RFC3339Nano)) - AssertEqual(t, expected, buf.String()) + testTime := time.Date(2024, 01, 02, 15, 04, 05, 123456789, time.UTC) + tests := []struct { + name string + timeFormat string + attrs []slog.Attr + want string + }{ + { + name: "DateTime", + timeFormat: time.DateTime, + want: "2024-01-02 15:04:05\n", + }, + { + name: "RFC3339Nano", + timeFormat: time.RFC3339Nano, + want: "2024-01-02T15:04:05.123456789Z\n", + }, + { + name: "Kitchen", + timeFormat: time.Kitchen, + want: "3:04PM\n", + }, + { + name: "EmptyFormat", + timeFormat: "", // should default to DateTime + want: "2024-01-02 15:04:05\n", + }, + { + name: "CustomFormat", + timeFormat: "2006/01/02 15:04:05.000 MST", + want: "2024/01/02 15:04:05.123 UTC\n", + }, + { + name: "also formats attrs", + timeFormat: time.Kitchen, + attrs: []slog.Attr{slog.Time("foo", time.Date(2025, 01, 02, 5, 03, 05, 22, time.UTC))}, + want: "3:04PM foo=5:03AM\n", + }, + } + + for _, tt := range tests { + ht := &handlerTest{ + name: tt.name, + time: testTime, + opts: HandlerOptions{ + TimeFormat: tt.timeFormat, + NoColor: true, + HeaderFormat: "%t %m %a", + }, + attrs: tt.attrs, + want: tt.want, + } + t.Run(tt.name, ht.run) + } } // Handlers should not log the time field if it is zero. // '- If r.Time is the zero time, ignore the time.' // https://pkg.go.dev/log/slog@master#Handler func TestHandler_TimeZero(t *testing.T) { - buf := bytes.Buffer{} - h := NewHandler(&buf, &HandlerOptions{TimeFormat: time.RFC3339Nano, NoColor: true}) - rec := slog.NewRecord(time.Time{}, slog.LevelInfo, "foobar", 0) - AssertNoError(t, h.Handle(context.Background(), rec)) - - expected := fmt.Sprintf("INF foobar\n") - AssertEqual(t, expected, buf.String()) -} - -func TestHandler_NoColor(t *testing.T) { - buf := bytes.Buffer{} - h := NewHandler(&buf, &HandlerOptions{NoColor: true}) - now := time.Now() - rec := slog.NewRecord(now, slog.LevelInfo, "foobar", 0) - AssertNoError(t, h.Handle(context.Background(), rec)) - - expected := fmt.Sprintf("%s INF foobar\n", now.Format(time.DateTime)) - AssertEqual(t, expected, buf.String()) + handlerTest{ + opts: HandlerOptions{TimeFormat: time.RFC3339Nano, NoColor: true}, + msg: "foobar", + want: "INF foobar\n", + }.run(t) } type theStringer struct{} @@ -72,206 +136,1270 @@ func (v *theValuer) LogValue() slog.Value { return slog.StringValue(fmt.Sprintf("The word is '%s'", v.word)) } -func TestHandler_Attr(t *testing.T) { - buf := bytes.Buffer{} - h := NewHandler(&buf, &HandlerOptions{NoColor: true}) - now := time.Now() - rec := slog.NewRecord(now, slog.LevelInfo, "foobar", 0) - rec.AddAttrs( - slog.Bool("bool", true), - slog.Int("int", -12), - slog.Uint64("uint", 12), - slog.Float64("float", 3.14), - slog.String("foo", "bar"), - slog.Time("time", now), - slog.Duration("dur", time.Second), - slog.Group("group", slog.String("foo", "bar"), slog.Group("subgroup", slog.String("foo", "bar"))), - slog.Any("err", errors.New("the error")), - slog.Any("stringer", theStringer{}), - slog.Any("nostringer", noStringer{Foo: "bar"}), - // Resolve LogValuer items in addition to Stringer items. - // '- Attr's values should be resolved.' - // https://pkg.go.dev/log/slog@master#Handler - // https://pkg.go.dev/log/slog@master#LogValuer - slog.Any("valuer", &theValuer{"distant"}), - // Handlers are supposed to avoid logging empty attributes. - // '- If an Attr's key and value are both the zero value, ignore the Attr.' - // https://pkg.go.dev/log/slog@master#Handler - slog.Attr{}, - slog.Any("", nil), - ) - AssertNoError(t, h.Handle(context.Background(), rec)) - - expected := fmt.Sprintf("%s INF foobar bool=true int=-12 uint=12 float=3.14 foo=bar time=%s dur=1s group.foo=bar group.subgroup.foo=bar err=the error stringer=stringer nostringer={bar} valuer=The word is 'distant'\n", now.Format(time.DateTime), now.Format(time.DateTime)) - AssertEqual(t, expected, buf.String()) +type formatterError struct { + error } -// Handlers should not log groups (or subgroups) without fields. -// '- If a group has no Attrs (even if it has a non-empty key), ignore it.' -// https://pkg.go.dev/log/slog@master#Handler -func TestHandler_GroupEmpty(t *testing.T) { - buf := bytes.Buffer{} - h := NewHandler(&buf, &HandlerOptions{NoColor: true}) - now := time.Now() - rec := slog.NewRecord(now, slog.LevelInfo, "foobar", 0) - rec.AddAttrs( - slog.Group("group", slog.String("foo", "bar")), - slog.Group("empty"), - ) - AssertNoError(t, h.Handle(context.Background(), rec)) - - expected := fmt.Sprintf("%s INF foobar group.foo=bar\n", now.Format(time.DateTime)) - AssertEqual(t, expected, buf.String()) +func (e *formatterError) Format(f fmt.State, verb rune) { + if verb == 'v' && f.Flag('+') { + _, _ = io.WriteString(f, "formatted ") + } + _, _ = io.WriteString(f, e.Error()) } -// Handlers should expand groups named "" (the empty string) into the enclosing log record. -// '- If a group's key is empty, inline the group's Attrs.' -// https://pkg.go.dev/log/slog@master#Handler -func TestHandler_GroupInline(t *testing.T) { - buf := bytes.Buffer{} - h := NewHandler(&buf, &HandlerOptions{NoColor: true}) - now := time.Now() - rec := slog.NewRecord(now, slog.LevelInfo, "foobar", 0) - rec.AddAttrs( - slog.Group("group", slog.String("foo", "bar")), - slog.Group("", slog.String("foo", "bar")), - ) - AssertNoError(t, h.Handle(context.Background(), rec)) - - expected := fmt.Sprintf("%s INF foobar group.foo=bar foo=bar\n", now.Format(time.DateTime)) - AssertEqual(t, expected, buf.String()) +func TestHandler_Attr(t *testing.T) { + testTime := time.Date(2024, 01, 02, 15, 04, 05, 123456789, time.UTC) + handlerTest{ + opts: HandlerOptions{NoColor: true}, + msg: "foobar", + time: testTime, + attrs: []slog.Attr{ + slog.Bool("bool", true), + slog.Int("int", -12), + slog.Uint64("uint", 12), + slog.Float64("float", 3.14), + slog.String("foo", "bar"), + slog.Time("time", testTime), + slog.Duration("dur", time.Second), + slog.Group("group", slog.String("foo", "bar"), slog.Group("subgroup", slog.String("foo", "bar"))), + slog.Any("err", errors.New("the error")), + slog.Any("formattedError", &formatterError{errors.New("the error")}), + slog.Any("stringer", theStringer{}), + slog.Any("nostringer", noStringer{Foo: "bar"}), + // Resolve LogValuer items in addition to Stringer items. + // '- Attr's values should be resolved.' + // https://pkg.go.dev/log/slog@master#Handler + // https://pkg.go.dev/log/slog@master#LogValuer + slog.Any("valuer", &theValuer{"distant"}), + // Handlers are supposed to avoid logging empty attributes. + // '- If an Attr's key and value are both the zero value, ignore the Attr.' + // https://pkg.go.dev/log/slog@master#Handler + slog.Attr{}, + slog.Any("", nil), + }, + want: "2024-01-02 15:04:05 INF foobar bool=true int=-12 uint=12 float=3.14 foo=bar time=2024-01-02 15:04:05 dur=1s group.foo=bar group.subgroup.foo=bar err=the error formattedError=formatted the error stringer=stringer nostringer={bar} valuer=The word is 'distant'\n", + }.run(t) } -// A Handler should call Resolve on attribute values in groups. -// https://cs.opensource.google/go/x/exp/+/0dcbfd60:slog/slogtest/slogtest.go -func TestHandler_GroupResolve(t *testing.T) { - buf := bytes.Buffer{} - h := NewHandler(&buf, &HandlerOptions{NoColor: true}) - now := time.Now() - rec := slog.NewRecord(now, slog.LevelInfo, "foobar", 0) - rec.AddAttrs( - slog.Group("group", "stringer", theStringer{}, "valuer", &theValuer{"surreal"}), - ) - AssertNoError(t, h.Handle(context.Background(), rec)) - - expected := fmt.Sprintf("%s INF foobar group.stringer=stringer group.valuer=The word is 'surreal'\n", now.Format(time.DateTime)) - AssertEqual(t, expected, buf.String()) +func TestHandler_AttrsWithNewlines(t *testing.T) { + tests := []struct { + handlerTest + altWant string + }{ + { + handlerTest: handlerTest{ + name: "single attr", + attrs: []slog.Attr{ + slog.String("foo", "line one\nline two"), + }, + want: "INF multiline attrs foo=line one\nline two\n", + }, + altWant: "INF multiline attrs\n=== foo ===\nline one\nline two\n", + }, + { + handlerTest: handlerTest{ + name: "multiple attrs", + attrs: []slog.Attr{ + slog.String("foo", "line one\nline two"), + slog.String("bar", "line three\nline four"), + }, + want: "INF multiline attrs foo=line one\nline two bar=line three\nline four\n", + }, + altWant: "INF multiline attrs\n=== foo ===\nline one\nline two\n=== bar ===\nline three\nline four\n", + }, + { + handlerTest: handlerTest{ + name: "sort multiline attrs to end", + attrs: []slog.Attr{ + slog.String("size", "big"), + slog.String("foo", "line one\nline two"), + slog.String("weight", "heavy"), + slog.String("bar", "line three\nline four"), + slog.String("color", "red"), + }, + want: "INF multiline attrs size=big weight=heavy color=red foo=line one\nline two bar=line three\nline four\n", + }, + altWant: "INF multiline attrs size=big weight=heavy color=red\n=== foo ===\nline one\nline two\n=== bar ===\nline three\nline four\n", + }, + { + handlerTest: handlerTest{ + name: "multiline message", + msg: "multiline\nmessage", + want: "INF multiline\nmessage\n", + }, + altWant: "INF multiline\nmessage\n", + }, + { + handlerTest: handlerTest{ + name: "preserve leading and trailing newlines", + attrs: []slog.Attr{ + slog.String("foo", "\nline one\nline two\n"), + slog.String("bar", "line three\nline four\n"), + }, + want: "INF multiline attrs foo=\nline one\nline two\n bar=line three\nline four\n", + }, + altWant: "INF multiline attrs\n=== foo ===\n\nline one\nline two\n\n=== bar ===\nline three\nline four\n\n", + }, + { + handlerTest: handlerTest{ + name: "multiline attr using WithAttrs", + handlerFunc: func(h slog.Handler) slog.Handler { + return h.WithAttrs([]slog.Attr{ + slog.String("foo", "line one\nline two"), + }) + }, + attrs: []slog.Attr{slog.String("bar", "baz")}, + want: "INF multiline attrs bar=baz foo=line one\nline two\n", + }, + altWant: "INF multiline attrs bar=baz\n=== foo ===\nline one\nline two\n", + }, + { + handlerTest: handlerTest{ + name: "multiline header value", + opts: HandlerOptions{NoColor: true, HeaderFormat: "%l %[foo]h > %m"}, + attrs: []slog.Attr{ + slog.String("foo", "line one\nline two"), + }, + want: "INF line one\nline two > multiline attrs\n", + }, + altWant: "INF line one\nline two > multiline attrs\n", + }, + } + + for _, test := range tests { + if test.msg == "" { + test.msg = "multiline attrs" + } + test.opts.NoColor = true + t.Run(test.name+" - old multiline", func(t *testing.T) { + oldValue := internal.FeatureFlagNewMultilineAttrs + internal.FeatureFlagNewMultilineAttrs = false + t.Cleanup(func() { + internal.FeatureFlagNewMultilineAttrs = oldValue + }) + test.run(t) + }) + test.want = test.altWant + t.Run(test.name+" - new multiline", func(t *testing.T) { + oldValue := internal.FeatureFlagNewMultilineAttrs + internal.FeatureFlagNewMultilineAttrs = true + t.Cleanup(func() { + internal.FeatureFlagNewMultilineAttrs = oldValue + }) + test.run(t) + }) + } } -func TestHandler_WithAttr(t *testing.T) { - buf := bytes.Buffer{} - h := NewHandler(&buf, &HandlerOptions{NoColor: true}) - now := time.Now() - rec := slog.NewRecord(now, slog.LevelInfo, "foobar", 0) - h2 := h.WithAttrs([]slog.Attr{ - slog.Bool("bool", true), - slog.Int("int", -12), - slog.Uint64("uint", 12), - slog.Float64("float", 3.14), - slog.String("foo", "bar"), - slog.Time("time", now), - slog.Duration("dur", time.Second), - // A Handler should call Resolve on attribute values from WithAttrs. - // https://cs.opensource.google/go/x/exp/+/0dcbfd60:slog/slogtest/slogtest.go - slog.Any("stringer", theStringer{}), - slog.Any("valuer", &theValuer{"awesome"}), - slog.Group("group", - slog.String("foo", "bar"), - slog.Group("subgroup", - slog.String("foo", "bar"), - ), - // A Handler should call Resolve on attribute values in groups from WithAttrs. +func TestHandler_Groups(t *testing.T) { + tests := []handlerTest{ + { + name: "single group", + attrs: []slog.Attr{ + slog.Group("group", slog.String("foo", "bar")), + }, + want: "INF single group group.foo=bar\n", + }, + { + // '- If a group has no Attrs (even if it has a non-empty key), ignore it.' + // https://pkg.go.dev/log/slog@master#Handler + name: "empty groups should be elided", + attrs: []slog.Attr{ + slog.Group("group", slog.String("foo", "bar")), + slog.Group("empty"), + }, + want: "INF empty groups should be elided group.foo=bar\n", + }, + { + // Handlers should expand groups named "" (the empty string) into the enclosing log record. + // '- If a group's key is empty, inline the group's Attrs.' + // https://pkg.go.dev/log/slog@master#Handler + name: "inline group", + attrs: []slog.Attr{ + slog.Group("group", slog.String("foo", "bar")), + slog.Group("", slog.String("foo", "bar")), + }, + want: "INF inline group group.foo=bar foo=bar\n", + }, + { + // A Handler should call Resolve on attribute values in groups. // https://cs.opensource.google/go/x/exp/+/0dcbfd60:slog/slogtest/slogtest.go - "stringer", theStringer{}, - "valuer", &theValuer{"pizza"}, - )}) - AssertNoError(t, h2.Handle(context.Background(), rec)) + name: "groups with valuer members", + attrs: []slog.Attr{ + slog.Group("group", "stringer", theStringer{}, "valuer", &theValuer{"surreal"}), + }, + want: "INF groups with valuer members group.stringer=stringer group.valuer=The word is 'surreal'\n", + }, + } + + for _, test := range tests { + test.opts.NoColor = true + test.msg = test.name + t.Run(test.name, test.run) + } +} - expected := fmt.Sprintf("%s INF foobar bool=true int=-12 uint=12 float=3.14 foo=bar time=%s dur=1s stringer=stringer valuer=The word is 'awesome' group.foo=bar group.subgroup.foo=bar group.stringer=stringer group.valuer=The word is 'pizza'\n", now.Format(time.DateTime), now.Format(time.DateTime)) - AssertEqual(t, expected, buf.String()) +func TestHandler_WithAttr(t *testing.T) { + testTime := time.Date(2024, 01, 02, 15, 04, 05, 123456789, time.UTC) - buf.Reset() - AssertNoError(t, h.Handle(context.Background(), rec)) - AssertEqual(t, fmt.Sprintf("%s INF foobar\n", now.Format(time.DateTime)), buf.String()) + tests := []handlerTest{ + { + name: "with attrs", + handlerFunc: func(h slog.Handler) slog.Handler { + return h.WithAttrs([]slog.Attr{ + slog.Bool("bool", true), + slog.Int("int", -12), + slog.Uint64("uint", 12), + slog.Float64("float", 3.14), + slog.String("foo", "bar"), + slog.Time("time", testTime), + slog.Duration("dur", time.Second), + // A Handler should call Resolve on attribute values from WithAttrs. + // https://cs.opensource.google/go/x/exp/+/0dcbfd60:slog/slogtest/slogtest.go + slog.Any("stringer", theStringer{}), + slog.Any("valuer", &theValuer{"awesome"}), + slog.Group("group", + slog.String("foo", "bar"), + slog.Group("subgroup", + slog.String("foo", "bar"), + ), + // A Handler should call Resolve on attribute values in groups from WithAttrs. + // https://cs.opensource.google/go/x/exp/+/0dcbfd60:slog/slogtest/slogtest.go + "stringer", theStringer{}, + "valuer", &theValuer{"pizza"}, + ), + }) + }, + msg: "foobar", + time: testTime, + want: "2024-01-02 15:04:05 INF foobar bool=true int=-12 uint=12 float=3.14 foo=bar time=2024-01-02 15:04:05 dur=1s stringer=stringer valuer=The word is 'awesome' group.foo=bar group.subgroup.foo=bar group.stringer=stringer group.valuer=The word is 'pizza'\n", + }, + { + name: "multiple withAttrs", + handlerFunc: func(h slog.Handler) slog.Handler { + return h.WithAttrs([]slog.Attr{ + slog.String("foo", "bar"), + }).WithAttrs([]slog.Attr{ + slog.String("baz", "buz"), + }) + }, + want: "INF multiple withAttrs foo=bar baz=buz\n", + }, + { + name: "withAttrs and headers", + opts: HandlerOptions{HeaderFormat: "%l %[foo]h %[bar]h > %m"}, + handlerFunc: func(h slog.Handler) slog.Handler { + return h.WithAttrs([]slog.Attr{ + slog.String("foo", "bar"), + }) + }, + want: "INF bar > withAttrs and headers\n", + }, + } + + for _, test := range tests { + test.opts.NoColor = true + if test.msg == "" { + test.msg = test.name + } + t.Run(test.name, test.run) + } + + t.Run("state isolation", func(t *testing.T) { + // test to make sure the way that WithAttrs() copies the cached headers doesn't leak + // headers back to the parent handler or to subsequent Handle() calls (i.e. ensure that + // the headers slice is copied at the right times). + + buf := bytes.Buffer{} + h := NewHandler(&buf, &HandlerOptions{ + HeaderFormat: "%l %[foo]h %[bar]h > %m", + TimeFormat: "0", + NoColor: true, + }) + + assertLog := func(t *testing.T, handler slog.Handler, want string, attrs ...slog.Attr) { + buf.Reset() + rec := slog.NewRecord(time.Time{}, slog.LevelInfo, "with headers", 0) + + rec.AddAttrs(attrs...) + + AssertNoError(t, handler.Handle(context.Background(), rec)) + AssertEqual(t, want, buf.String()) + } + + assertLog(t, h, "INF bar > with headers\n", slog.String("foo", "bar")) + + h2 := h.WithAttrs([]slog.Attr{slog.String("foo", "baz")}) + assertLog(t, h2, "INF baz > with headers\n") + + h3 := h2.WithAttrs([]slog.Attr{slog.String("foo", "buz")}) + assertLog(t, h3, "INF buz > with headers\n") + // creating h3 should not have affected h2 + assertLog(t, h2, "INF baz > with headers\n") + + // overriding attrs shouldn't affect the handler + assertLog(t, h2, "INF biz > with headers\n", slog.String("foo", "biz")) + assertLog(t, h2, "INF baz > with headers\n") + + }) } func TestHandler_WithGroup(t *testing.T) { - buf := bytes.Buffer{} - h := NewHandler(&buf, &HandlerOptions{NoColor: true}) - now := time.Now() - rec := slog.NewRecord(now, slog.LevelInfo, "foobar", 0) - rec.Add("int", 12) - h2 := h.WithGroup("group1").WithAttrs([]slog.Attr{slog.String("foo", "bar")}) - AssertNoError(t, h2.Handle(context.Background(), rec)) - expected := fmt.Sprintf("%s INF foobar group1.foo=bar group1.int=12\n", now.Format(time.DateTime)) - AssertEqual(t, expected, buf.String()) - buf.Reset() - - h3 := h2.WithGroup("group2") - AssertNoError(t, h3.Handle(context.Background(), rec)) - expected = fmt.Sprintf("%s INF foobar group1.foo=bar group1.group2.int=12\n", now.Format(time.DateTime)) - AssertEqual(t, expected, buf.String()) - - buf.Reset() - AssertNoError(t, h.Handle(context.Background(), rec)) - AssertEqual(t, fmt.Sprintf("%s INF foobar int=12\n", now.Format(time.DateTime)), buf.String()) + + tests := []handlerTest{ + { + name: "withGroup", + handlerFunc: func(h slog.Handler) slog.Handler { + return h.WithGroup("group1") + }, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "INF withGroup group1.foo=bar\n", + }, + { + name: "withGroup and headers", + opts: HandlerOptions{HeaderFormat: "%l %[group1.foo]h %[bar]h > %m %a"}, + handlerFunc: func(h slog.Handler) slog.Handler { + return h.WithGroup("group1").WithAttrs([]slog.Attr{slog.String("foo", "bar"), slog.String("bar", "baz")}) + }, + want: "INF bar > withGroup and headers group1.bar=baz\n", + }, + { + name: "withGroup and withAttrs", + handlerFunc: func(h slog.Handler) slog.Handler { + return h.WithAttrs([]slog.Attr{slog.String("bar", "baz")}).WithGroup("group1").WithAttrs([]slog.Attr{slog.String("foo", "bar")}) + }, + attrs: []slog.Attr{slog.String("baz", "foo")}, + want: "INF withGroup and withAttrs bar=baz group1.foo=bar group1.baz=foo\n", + }, + } + + for _, test := range tests { + test.opts.NoColor = true + if test.msg == "" { + test.msg = test.name + } + t.Run(test.name, test.run) + } + + t.Run("state isolation", func(t *testing.T) { + // test to make sure the way that WithGroup() caches state doesn't leak + // back to the parent handler or to subsequent Handle() calls + + buf := bytes.Buffer{} + h := NewHandler(&buf, &HandlerOptions{ + HeaderFormat: "%m %a", + TimeFormat: "0", + NoColor: true, + // the only state which WithGroup() might corrupt is the list of groups + // passed to ReplaceAttr. So we use a custom ReplaceAttr to test that + // state is not leaked. + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + if a.Key == "foo" { + return slog.String("foo", strings.Join(groups, ".")) + } + return a + }, + }) + + assertLog := func(t *testing.T, handler slog.Handler, want string, attrs ...slog.Attr) { + t.Helper() + + buf.Reset() + rec := slog.NewRecord(time.Time{}, slog.LevelInfo, "state isolation", 0) + + rec.AddAttrs(attrs...) + + AssertNoError(t, handler.Handle(context.Background(), rec)) + AssertEqual(t, want, buf.String()) + } + + assertLog(t, h, "state isolation foo=\n", slog.String("foo", "bar")) + + h2 := h.WithGroup("group1") + assertLog(t, h2, "state isolation group1.foo=group1\n", slog.String("foo", "bar")) + + h3 := h.WithGroup("group2") + assertLog(t, h3, "state isolation group2.foo=group2\n", slog.String("foo", "bar")) + // creating h3 should not have affected h2 + assertLog(t, h2, "state isolation group1.foo=group1\n", slog.String("foo", "bar")) + + // overriding attrs shouldn't affect the handler + assertLog(t, h2, "state isolation group1.group3.foo=group1.group3\n", slog.Group("group3", slog.String("foo", "biz"))) + assertLog(t, h3, "state isolation group2.group3.foo=group2.group3\n", slog.Group("group3", slog.String("foo", "biz"))) + + }) +} + +type valuer struct { + v slog.Value } -func TestHandler_Levels(t *testing.T) { - levels := map[slog.Level]string{ - slog.LevelDebug - 1: "DBG-1", - slog.LevelDebug: "DBG", - slog.LevelDebug + 1: "DBG+1", - slog.LevelInfo: "INF", - slog.LevelInfo + 1: "INF+1", - slog.LevelWarn: "WRN", - slog.LevelWarn + 1: "WRN+1", - slog.LevelError: "ERR", - slog.LevelError + 1: "ERR+1", +func (v valuer) LogValue() slog.Value { + return v.v +} + +func TestHandler_ReplaceAttr(t *testing.T) { + pc, file, line, _ := runtime.Caller(0) + cwd, _ := os.Getwd() + file, _ = filepath.Rel(cwd, file) + sourceField := fmt.Sprintf("%s:%d", file, line) + + replaceAttrWith := func(key string, out slog.Attr) func(*testing.T, []string, slog.Attr) slog.Attr { + return func(t *testing.T, s []string, a slog.Attr) slog.Attr { + if a.Key == key { + return out + } + return a + } } - for l := range levels { - t.Run(l.String(), func(t *testing.T) { + awesomeVal := slog.Any("valuer", valuer{slog.StringValue("awesome")}) + + awesomeValuer := valuer{slog.StringValue("awesome")} + + tests := []struct { + name string + replaceAttr func(*testing.T, []string, slog.Attr) slog.Attr + want string + modrec func(*slog.Record) + noSource bool + groups []string + }{ + { + name: "no replaceattrs", + want: "2010-05-06 07:08:09 INF " + sourceField + " > foobar size=12 color=red\n", + }, + { + name: "not called for empty timestamp and disabled source", + modrec: func(r *slog.Record) { + r.Time = time.Time{} + }, + noSource: true, + want: "INF foobar size=12 color=red\n", + replaceAttr: func(t *testing.T, s []string, a slog.Attr) slog.Attr { + switch a.Key { + case slog.TimeKey, slog.SourceKey: + t.Errorf("replaceAttr should not have been called for %v", a) + } + return a + }, + }, + { + name: "not called for groups", + modrec: func(r *slog.Record) { r.Add(slog.Group("l1", slog.String("flavor", "vanilla"))) }, + replaceAttr: func(t *testing.T, s []string, a slog.Attr) slog.Attr { + if a.Key == "l1" { + t.Errorf("should not have been called on group attrs, was called on %v", a) + } + return a + }, + want: "2010-05-06 07:08:09 INF " + sourceField + " > foobar size=12 color=red l1.flavor=vanilla\n", + }, + { + name: "groups arg", + groups: []string{"l1", "l2"}, + modrec: func(r *slog.Record) { + r.Add(slog.Group("l3", slog.String("flavor", "vanilla"))) + r.Add(slog.Int("weight", 23)) + }, + replaceAttr: func(t *testing.T, s []string, a slog.Attr) slog.Attr { + wantGroups := []string{"l1", "l2"} + switch a.Key { + case slog.TimeKey, slog.SourceKey, slog.MessageKey, slog.LevelKey: + if len(s) != 0 { + t.Errorf("for builtin attr %v, expected no groups, got %v", a.Key, s) + } + case "flavor": + wantGroups = []string{"l1", "l2", "l3"} + fallthrough + default: + if !reflect.DeepEqual(wantGroups, s) { + t.Errorf("for %v attr, expected %v, got %v", a.Key, wantGroups, s) + } + } + return slog.String(a.Key, a.Key) + }, + want: "time level source > msg l1.l2.size=size l1.l2.color=color l1.l2.l3.flavor=flavor l1.l2.weight=weight\n", + }, + { + name: "clear timestamp", + replaceAttr: replaceAttrWith(slog.TimeKey, slog.Time(slog.TimeKey, time.Time{})), + want: "INF " + sourceField + " > foobar size=12 color=red\n", + }, + { + name: "clear timestamp attr", + replaceAttr: replaceAttrWith(slog.TimeKey, slog.Attr{}), + want: "INF " + sourceField + " > foobar size=12 color=red\n", + }, + { + name: "replace timestamp", + replaceAttr: replaceAttrWith(slog.TimeKey, slog.Time(slog.TimeKey, time.Date(2000, 2, 3, 4, 5, 6, 0, time.UTC))), + want: "2000-02-03 04:05:06 INF " + sourceField + " > foobar size=12 color=red\n", + }, + { + name: "replace timestamp with different kind", + replaceAttr: replaceAttrWith(slog.TimeKey, slog.String("color", "red")), + want: "red INF " + sourceField + " > foobar size=12 color=red\n", + }, + { + name: "replace timestamp with valuer", + replaceAttr: replaceAttrWith(slog.TimeKey, awesomeVal), + want: "awesome INF " + sourceField + " > foobar size=12 color=red\n", + }, + { + name: "replace timestamp with time valuer", + replaceAttr: replaceAttrWith(slog.TimeKey, slog.Any("valuer", valuer{slog.TimeValue(time.Date(2000, 2, 3, 4, 5, 6, 0, time.UTC))})), + want: "2000-02-03 04:05:06 INF " + sourceField + " > foobar size=12 color=red\n", + }, + { + name: "replace level", + replaceAttr: replaceAttrWith(slog.LevelKey, slog.Any(slog.LevelKey, slog.LevelWarn)), + want: "2010-05-06 07:08:09 WRN " + sourceField + " > foobar size=12 color=red\n", + }, + { + name: "clear level", + replaceAttr: replaceAttrWith(slog.LevelKey, slog.Any(slog.LevelKey, nil)), + want: "2010-05-06 07:08:09 " + sourceField + " > foobar size=12 color=red\n", + }, + { + name: "replace level with different kind", + replaceAttr: replaceAttrWith(slog.LevelKey, slog.String("color", "red")), + want: "2010-05-06 07:08:09 red " + sourceField + " > foobar size=12 color=red\n", + }, + { + name: "replace level with valuer", + replaceAttr: replaceAttrWith(slog.LevelKey, awesomeVal), + want: "2010-05-06 07:08:09 awesome " + sourceField + " > foobar size=12 color=red\n", + }, + { + name: "replace level with level valuer", + replaceAttr: replaceAttrWith(slog.LevelKey, slog.Any("valuer", valuer{slog.AnyValue(slog.LevelWarn)})), + want: "2010-05-06 07:08:09 WRN " + sourceField + " > foobar size=12 color=red\n", + }, + { + name: "clear source", + replaceAttr: replaceAttrWith(slog.SourceKey, slog.Any(slog.SourceKey, nil)), + want: "2010-05-06 07:08:09 INF foobar size=12 color=red\n", + }, + { + name: "replace source", + replaceAttr: replaceAttrWith(slog.SourceKey, slog.Any(slog.SourceKey, &slog.Source{ + File: filepath.Join(cwd, "path", "to", "file.go"), + Line: 33, + })), + want: "2010-05-06 07:08:09 INF path/to/file.go:33 > foobar size=12 color=red\n", + }, + { + name: "replace source with different kind", + replaceAttr: replaceAttrWith(slog.SourceKey, slog.String(slog.SourceKey, "red")), + want: "2010-05-06 07:08:09 INF red > foobar size=12 color=red\n", + }, + { + name: "replace source with valuer", + replaceAttr: replaceAttrWith(slog.SourceKey, slog.Any(slog.SourceKey, awesomeValuer)), + want: "2010-05-06 07:08:09 INF awesome > foobar size=12 color=red\n", + }, + { + name: "replace source with source valuer", + replaceAttr: replaceAttrWith(slog.SourceKey, slog.Any(slog.SourceKey, valuer{slog.AnyValue(&slog.Source{ + File: filepath.Join(cwd, "path", "to", "file.go"), + Line: 33, + })})), + want: "2010-05-06 07:08:09 INF path/to/file.go:33 > foobar size=12 color=red\n", + }, + { + name: "empty source", // won't be called because PC is 0 + modrec: func(r *slog.Record) { r.PC = 0 }, + replaceAttr: func(t *testing.T, s []string, a slog.Attr) slog.Attr { + if a.Key == slog.SourceKey { + t.Errorf("should not have been called on source attr, was called on %v", a) + } + return a + }, + want: "2010-05-06 07:08:09 INF foobar size=12 color=red\n", + }, + { + name: "clear message", + replaceAttr: replaceAttrWith(slog.MessageKey, slog.Any(slog.MessageKey, nil)), + want: "2010-05-06 07:08:09 INF " + sourceField + " > size=12 color=red\n", + }, + { + name: "replace message", + replaceAttr: replaceAttrWith(slog.MessageKey, slog.String(slog.MessageKey, "barbaz")), + want: "2010-05-06 07:08:09 INF " + sourceField + " > barbaz size=12 color=red\n", + }, + { + name: "replace message with different kind", + replaceAttr: replaceAttrWith(slog.MessageKey, slog.Int(slog.MessageKey, 5)), + want: "2010-05-06 07:08:09 INF " + sourceField + " > 5 size=12 color=red\n", + }, + { + name: "replace message with valuer", + replaceAttr: replaceAttrWith(slog.MessageKey, awesomeVal), + want: "2010-05-06 07:08:09 INF " + sourceField + " > awesome size=12 color=red\n", + }, + { + name: "clear attr", + replaceAttr: replaceAttrWith("size", slog.Attr{}), + want: "2010-05-06 07:08:09 INF " + sourceField + " > foobar color=red\n", + }, + { + name: "replace attr", + replaceAttr: replaceAttrWith("size", slog.String("flavor", "vanilla")), + want: "2010-05-06 07:08:09 INF " + sourceField + " > foobar flavor=vanilla color=red\n", + }, + { + name: "replace with group attrs", + replaceAttr: replaceAttrWith("size", slog.Group("l1", slog.String("flavor", "vanilla"))), + want: "2010-05-06 07:08:09 INF " + sourceField + " > foobar l1.flavor=vanilla color=red\n", + }, + // { + // name: "replace header", + // } + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { buf := bytes.Buffer{} - h := NewHandler(&buf, &HandlerOptions{Level: l, NoColor: true}) - for ll, s := range levels { - AssertEqual(t, ll >= l, h.Enabled(context.Background(), ll)) - now := time.Now() - rec := slog.NewRecord(now, ll, "foobar", 0) - if ll >= l { - AssertNoError(t, h.Handle(context.Background(), rec)) - AssertEqual(t, fmt.Sprintf("%s %s foobar\n", now.Format(time.DateTime), s), buf.String()) - buf.Reset() + + rec := slog.NewRecord(time.Date(2010, 5, 6, 7, 8, 9, 0, time.UTC), slog.LevelInfo, "foobar", pc) + rec.Add("size", 12, "color", "red") + + if test.modrec != nil { + test.modrec(&rec) + } + + var replaceAttr func([]string, slog.Attr) slog.Attr + if test.replaceAttr != nil { + replaceAttr = func(s []string, a slog.Attr) slog.Attr { + return test.replaceAttr(t, s, a) } } + + var h slog.Handler = NewHandler(&buf, &HandlerOptions{AddSource: !test.noSource, NoColor: true, ReplaceAttr: replaceAttr}) + + for _, group := range test.groups { + h = h.WithGroup(group) + } + + AssertNoError(t, h.Handle(context.Background(), rec)) + + AssertEqual(t, test.want, buf.String()) + }) } + } -func TestHandler_Source(t *testing.T) { - buf := bytes.Buffer{} - h := NewHandler(&buf, &HandlerOptions{NoColor: true, AddSource: true}) - h2 := NewHandler(&buf, &HandlerOptions{NoColor: true, AddSource: false}) +func TestHandler_TruncateSourcePath(t *testing.T) { + origCwd := cwd + t.Cleanup(func() { cwd = origCwd }) + + cwd = "/usr/share/proj" + absSource := slog.Source{ + File: "/var/proj/red/blue/green/yellow/main.go", + Line: 23, + } + relSource := slog.Source{ + File: "/usr/share/proj/red/blue/green/yellow/main.go", + Line: 23, + } + + tests := []handlerTest{ + { + name: "abs 1", + opts: HandlerOptions{TruncateSourcePath: 1}, + attrs: []slog.Attr{slog.Any("source", &absSource)}, + want: "INF source=main.go:23", + }, + { + name: "abs 2", + opts: HandlerOptions{TruncateSourcePath: 2}, + attrs: []slog.Attr{slog.Any("source", &absSource)}, + want: "INF source=yellow/main.go:23", + }, + { + name: "abs 3", + opts: HandlerOptions{TruncateSourcePath: 3}, + attrs: []slog.Attr{slog.Any("source", &absSource)}, + want: "INF source=green/yellow/main.go:23", + }, + { + name: "abs 4", + opts: HandlerOptions{TruncateSourcePath: 4}, + attrs: []slog.Attr{slog.Any("source", &absSource)}, + want: "INF source=blue/green/yellow/main.go:23", + }, + { + name: "default", + attrs: []slog.Attr{slog.Any("source", &absSource)}, + want: "INF source=/var/proj/red/blue/green/yellow/main.go:23", + }, + { + name: "relative", + attrs: []slog.Attr{slog.Any("source", &relSource)}, + want: "INF source=red/blue/green/yellow/main.go:23", + }, + { + name: "relative 1", + opts: HandlerOptions{TruncateSourcePath: 1}, + attrs: []slog.Attr{slog.Any("source", &relSource)}, + want: "INF source=main.go:23", + }, + { + name: "relative 2", + opts: HandlerOptions{TruncateSourcePath: 2}, + attrs: []slog.Attr{slog.Any("source", &relSource)}, + want: "INF source=yellow/main.go:23", + }, + { + name: "relative 3", + opts: HandlerOptions{TruncateSourcePath: 3}, + attrs: []slog.Attr{slog.Any("source", &relSource)}, + want: "INF source=green/yellow/main.go:23", + }, + { + name: "relative 4", + opts: HandlerOptions{TruncateSourcePath: 4}, + attrs: []slog.Attr{slog.Any("source", &relSource)}, + want: "INF source=blue/green/yellow/main.go:23", + }, + } + + for _, tt := range tests { + tt.opts.NoColor = true + tt.want += "\n" + t.Run(tt.name, tt.run) + } +} + +func TestHandler_CollapseSpaces(t *testing.T) { + tests2 := []struct { + desc, format, want string + }{ + {"default", "", "INF msg"}, + {"trailing space", "%l ", "INF"}, + {"trailing space", "%l %t ", "INF"}, + {"leading space", " %l", "INF"}, + {"leading space", " %t %l", "INF"}, + {"unanchored", "%l%t %t%l", "INF INF"}, + {"unanchored", "%l%t %l", "INF INF"}, + {"unanchored", "%l %t%l", "INF INF"}, + {"unanchored", "%l %t %l", "INF INF"}, + {"unanchored", "%l %t %t %l", "INF INF"}, + {"unanchored", "%l %t", "INF"}, + {"unanchored", "%t %l", "INF"}, + {"unanchored", "%l %t%t %l", "INF INF"}, + {"unanchored", "[%l %t]", "[INF]"}, + {"unanchored", "[%t %l]", "[INF]"}, + {"unanchored", "[%l %t %l]", "[INF INF]"}, + {"unanchored", "[%l%t %l]", "[INF INF]"}, + {"unanchored", "[%l %t%l]", "[INF INF]"}, + {"unanchored", "[%l%t %t%l]", "[INF INF]"}, + {"extra spaces", " %l %t %t %l ", "INF INF"}, + {"anchored", "%l %t > %m", "INF > msg"}, + {"anchored", "[%l] [%t] > %m", "[INF] [] > msg"}, + {"anchored", "[ %l %t]", "[ INF]"}, + {"anchored", "[%l %t ]", "[INF ]"}, + {"anchored", "[%t]", "[]"}, + {"anchored", "[ %t ]", "[ ]"}, + {"groups", "%l %{%t%} %l", "INF INF"}, + {"groups", "%l %{ %t %} %l", "INF INF"}, + {"groups", "%l %{ %t %l%} %l", "INF INF INF"}, + {"groups", "%l %{ %t %l %} %l", "INF INF INF"}, + {"groups", "%l %{%l %t %l %} %l", "INF INF INF INF"}, + {"groups", "%l %{ %l %t %l %} %l", "INF INF INF INF"}, + {"groups", "%l %{ %t %t %t %} %l", "INF INF"}, + {"groups", "%l%{%t %} > %m", "INF > msg"}, + {"groups", "%l%{ %t %}%l", "INFINF"}, + {"groups with strings", "%l %{> %t %} %l", "INF INF"}, + {"groups with strings", "%l %{> %t %t %} %l", "INF INF"}, + {"groups with strings", "%l %{%t %t > %} %l", "INF INF"}, + {"groups with strings", "%l %{[%t][%l][%t]%} > ", "INF [][INF][] >"}, + {"groups with strings", "%l %{[%t]%}%{[%l]%}%{[%t]%} > %m", "INF [INF] > msg"}, + {"padded header", "%l %[foo]5h > %m", "INF > msg"}, + {"nested groups", "%l %{ %{ %{ %t %} %} %} > %m", "INF > msg"}, + {"nested groups", "%l%{ %{ %{%t%}%}%} > %m", "INF > msg"}, + {"deeply nested groups", "%l%{ %{ %{ %{ %{ %{ %t %} %} %} %} %} %} > %m", "INF > msg"}, + } + + for _, tt := range tests2 { + ht := handlerTest{ + name: tt.desc, + msg: "msg", + opts: HandlerOptions{HeaderFormat: tt.format, NoColor: true}, + want: tt.want + "\n", + } + t.Run(ht.name, ht.run) + } +} + +func styled(s string, c ANSIMod) string { + if c == "" { + return s + } + return strings.Join([]string{string(c), s, string(ResetMod)}, "") +} + +func TestHandler_HeaderFormat_Groups(t *testing.T) { + theme := NewDefaultTheme() + tests := []handlerTest{ + { + name: "group not elided", + opts: HandlerOptions{HeaderFormat: "%l %{[%[foo]h]%} > %m", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "INF [bar] > groups\n", + }, + { + name: "group elided", + opts: HandlerOptions{HeaderFormat: "%l %{[%[foo]h]%} > %m", NoColor: true}, + want: "INF > groups\n", + }, + { + name: "group with only fixed strings not elided", + opts: HandlerOptions{HeaderFormat: "%l %{[fixed string]%} > %m", NoColor: true}, + want: "INF [fixed string] > groups\n", + }, + { + name: "two headers in group, both elided", + opts: HandlerOptions{HeaderFormat: "%l %{[%[foo]h %[bar]h]%} > %m", NoColor: true}, + want: "INF > groups\n", + }, + { + name: "two headers in group, one elided", + opts: HandlerOptions{HeaderFormat: "%l %{[%[foo]h %[bar]h]%} > %m", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "INF [bar] > groups\n", + }, + { + name: "two headers in group, neither elided", + opts: HandlerOptions{HeaderFormat: "%l %{[%[foo]h %[bar]h]%} > %m", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar"), slog.String("bar", "baz")}, + want: "INF [bar baz] > groups\n", + }, + { + name: "open group not closed", + opts: HandlerOptions{HeaderFormat: "%l %{ > %m", NoColor: true}, + want: "INF > groups\n", + }, + { + name: "closed group not opened", + opts: HandlerOptions{HeaderFormat: "%l %} > %m", NoColor: true}, + want: "INF > groups\n", + }, + { + name: "styled group", + opts: HandlerOptions{HeaderFormat: "%l %(source){ [%[foo]h] %} > %m"}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: strings.Join([]string{ + styled("INF", theme.LevelInfo), " ", + styled("[", theme.Source), + styled("bar", theme.Header), + styled("]", theme.Source), " ", + styled(">", theme.Header), " ", + styled("groups", theme.Message), + "\n"}, ""), + }, + { + name: "nested styled groups", + opts: HandlerOptions{HeaderFormat: "%l %(source){ [%[foo]h] %(message){ [%[bar]h] %} %} > %m"}, + attrs: []slog.Attr{slog.String("foo", "bar"), slog.String("bar", "baz")}, + want: strings.Join([]string{ + styled("INF", theme.LevelInfo), " ", + styled("[", theme.Source), + styled("bar", theme.Header), + styled("]", theme.Source), " ", + styled("[", theme.Message), + styled("baz", theme.Header), + styled("]", theme.Message), " ", + styled(">", theme.Header), " ", + styled("groups", theme.Message), + "\n"}, ""), + }, + { + name: "invalid style name", + opts: HandlerOptions{HeaderFormat: "%l %(nonexistent){ %[foo]h %} > %m", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "INF %!{(nonexistent)(INVALID_STYLE_MODIFIER) bar > groups\n", + }, + { + name: "unclosed style modifier", + opts: HandlerOptions{HeaderFormat: "%l %(source{ %[foo]h %} > %m", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "INF %!(source{(MISSING_CLOSING_PARENTHESIS) bar > groups\n", + }, + { + name: "empty style modifier", + opts: HandlerOptions{HeaderFormat: "%l %(){ %[foo]h %} > %m", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "INF bar > groups\n", + }, + } + + for _, tt := range tests { + tt.msg = "groups" + t.Run(tt.name, tt.run) + } +} + +// Add a test for header formats with groups +// nested +// extra open/close groups + +func TestHandler_HeaderFormat(t *testing.T) { pc, file, line, _ := runtime.Caller(0) - now := time.Now() - rec := slog.NewRecord(now, slog.LevelInfo, "foobar", pc) - AssertNoError(t, h.Handle(context.Background(), rec)) cwd, _ := os.Getwd() file, _ = filepath.Rel(cwd, file) - AssertEqual(t, fmt.Sprintf("%s INF %s:%d > foobar\n", now.Format(time.DateTime), file, line), buf.String()) - buf.Reset() - AssertNoError(t, h2.Handle(context.Background(), rec)) - AssertEqual(t, fmt.Sprintf("%s INF foobar\n", now.Format(time.DateTime)), buf.String()) - buf.Reset() - // If the PC is zero then this field and its associated group should not be logged. - // '- If r.PC is zero, ignore it.' - // https://pkg.go.dev/log/slog@master#Handler - rec.PC = 0 - AssertNoError(t, h.Handle(context.Background(), rec)) - AssertEqual(t, fmt.Sprintf("%s INF foobar\n", now.Format(time.DateTime)), buf.String()) + sourceField := fmt.Sprintf("%s:%d", file, line) + + testTime := time.Date(2024, 01, 02, 15, 04, 05, 123456789, time.UTC) + + tests := []handlerTest{ + { + name: "default", + opts: HandlerOptions{AddSource: true, NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "2024-01-02 15:04:05 INF " + sourceField + " > with headers foo=bar\n", + }, + { + name: "one header", + opts: HandlerOptions{HeaderFormat: "%l %[foo]h > %m %a", NoColor: true}, + attrs: []slog.Attr{ + slog.String("foo", "bar"), + slog.String("bar", "baz"), + }, + want: "INF bar > with headers bar=baz\n", + }, + { + name: "two headers", + opts: HandlerOptions{HeaderFormat: "%l %[foo]h %[bar]h > %m %a", NoColor: true}, + attrs: []slog.Attr{ + slog.String("foo", "bar"), + slog.String("bar", "baz"), + }, + want: "INF bar baz > with headers\n", + }, + { + name: "two headers alt order", + opts: HandlerOptions{HeaderFormat: "%l %[foo]h %[bar]h > %m %a", NoColor: true}, + attrs: []slog.Attr{ + slog.String("bar", "baz"), + slog.String("foo", "bar"), + }, + want: "INF bar baz > with headers\n", + }, + { + name: "missing headers", + opts: HandlerOptions{HeaderFormat: "%l %[foo]h %[bar]h > %m %a", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "INF bar > with headers\n", // missing headers are omitted + }, + { + name: "missing headers, no space", + opts: HandlerOptions{HeaderFormat: "%l%[foo]h%[bar]h>%m %a", NoColor: true}, // no spaces between headers or level/message + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "INFbar>with headers\n", + }, + { + name: "header without group prefix does not match attr in group", + opts: HandlerOptions{HeaderFormat: "%l %[foo]h > %m %a", NoColor: true}, // header is an attribute inside a group + attrs: []slog.Attr{slog.String("foo", "bar")}, + handlerFunc: func(h slog.Handler) slog.Handler { + return h.WithGroup("group1") + }, + want: "INF > with headers group1.foo=bar\n", // header is foo, not group1.foo + }, + { + name: "header with group prefix", + opts: HandlerOptions{HeaderFormat: "%l %[group1.foo]h > %m %a", NoColor: true}, // header is an attribute inside a group + attrs: []slog.Attr{slog.String("foo", "bar")}, + handlerFunc: func(h slog.Handler) slog.Handler { + return h.WithGroup("group1") + }, + want: "INF bar > with headers\n", + }, + { + name: "header in nested groups", + opts: HandlerOptions{HeaderFormat: "%l %[group1.group2.foo]h > %m %a", NoColor: true}, // header is an attribute inside a group + attrs: []slog.Attr{slog.String("foo", "bar")}, + handlerFunc: func(h slog.Handler) slog.Handler { + return h.WithGroup("group1").WithGroup("group2") + }, + want: "INF bar > with headers\n", + }, + { + name: "header in group attr, no match", + opts: HandlerOptions{HeaderFormat: "%l %[foo]h > %m %a", NoColor: true}, // header is an attribute inside a group + attrs: []slog.Attr{slog.Group("group1", slog.String("foo", "bar"))}, + want: "INF > with headers group1.foo=bar\n", + }, + { + name: "header in group attr, match", + opts: HandlerOptions{HeaderFormat: "%l %[group1.foo]h > %m %a", NoColor: true}, // header is an attribute inside a group + attrs: []slog.Attr{slog.Group("group1", slog.String("foo", "bar"))}, + want: "INF bar > with headers\n", + }, + { + name: "header and withGroup and nested group", + opts: HandlerOptions{HeaderFormat: "%l %[group1.foo]h %[group1.group2.bar]h > %m %a", NoColor: true}, // header is group2.attr0, attr0 is in root + attrs: []slog.Attr{slog.String("foo", "bar"), slog.Group("group2", slog.String("bar", "baz"))}, + handlerFunc: func(h slog.Handler) slog.Handler { + return h.WithGroup("group1") + }, + want: "INF bar baz > with headers\n", + }, + { + name: "no header", + opts: HandlerOptions{HeaderFormat: "%l > %m %a", NoColor: true}, // no header + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "INF > with headers foo=bar\n", + }, + { + name: "just level", + opts: HandlerOptions{HeaderFormat: "%l", NoColor: true}, // no header, no message + want: "INF\n", + }, + { + name: "just message", + opts: HandlerOptions{HeaderFormat: "%m", NoColor: true}, // just message + want: "with headers\n", + }, + { + name: "just attrs", + opts: HandlerOptions{HeaderFormat: "%a", NoColor: true}, // just attrs + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "foo=bar\n", + }, + { + name: "source not in the header", + handlerFunc: func(h slog.Handler) slog.Handler { + return h.WithGroup("group1").WithAttrs([]slog.Attr{slog.String("foo", "bar")}) + }, + opts: HandlerOptions{HeaderFormat: "%l > %m %a", NoColor: true, AddSource: true}, // header is foo, not source + want: "INF > with headers source=" + sourceField + " group1.foo=bar\n", + }, + { + name: "header matches a group attr should skip header", + attrs: []slog.Attr{slog.Group("group1", slog.String("foo", "bar"))}, + opts: HandlerOptions{HeaderFormat: "%l %[group1]h > %m %a", NoColor: true}, + want: "INF > with headers group1.foo=bar\n", + }, + { + name: "repeated header with capture", + opts: HandlerOptions{HeaderFormat: "%l %[foo]h %[foo]h > %m %a", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "INF bar > with headers\n", // Second header is ignored since foo was captured by first header + }, + { + name: "repeated timestamp, level and message fields", + opts: HandlerOptions{HeaderFormat: "%t %l %m %t %l %m %a", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "2024-01-02 15:04:05 INF with headers 2024-01-02 15:04:05 INF with headers foo=bar\n", + }, + { + name: "missing header and multiple spaces", + opts: HandlerOptions{HeaderFormat: "%l %[missing]h %[foo]h > %m %a", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "INF bar > with headers\n", + }, + { + name: "fixed width header left aligned", + opts: HandlerOptions{HeaderFormat: "%l %[foo]10h > %m %a", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "INF bar > with headers\n", + }, + { + name: "fixed width header right aligned", + opts: HandlerOptions{HeaderFormat: "%l %[foo]-10h > %m %a", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "INF bar > with headers\n", + }, + { + name: "fixed width header truncated", + opts: HandlerOptions{HeaderFormat: "%l %[foo]3h > %m %a", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "barbaz")}, + want: "INF bar > with headers\n", + }, + { + name: "fixed width header with spaces", + opts: HandlerOptions{HeaderFormat: "%l %[foo]10h %[bar]5h > %m %a", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "hello"), slog.String("bar", "world")}, + want: "INF hello world > with headers\n", + }, + { + name: "fixed width header missing attr", + opts: HandlerOptions{HeaderFormat: "%l %[missing]10h > %m %a", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "INF > with headers foo=bar\n", + }, + { + name: "non-abbreviated levels", + opts: HandlerOptions{HeaderFormat: "%L > %m %a", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "INFO > with headers foo=bar\n", + }, + { + name: "alternate text", + opts: HandlerOptions{HeaderFormat: "prefix [%l] [%[foo]h] %m suffix > %a", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "prefix [INF] [bar] with headers suffix >\n", + }, + { + name: "escaped percent", + opts: HandlerOptions{HeaderFormat: "prefix %% [%l] %m %a", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "prefix % [INF] with headers foo=bar\n", + }, + { + name: "missing verb", + opts: HandlerOptions{HeaderFormat: "%m % %a", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "with headers %!(MISSING_VERB) foo=bar\n", + }, + { + name: "missing verb with modifiers", + opts: HandlerOptions{HeaderFormat: "%m %[slog]-4 %a", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "with headers %!(MISSING_VERB) foo=bar\n", + }, + { + name: "invalid right align modifier", + opts: HandlerOptions{HeaderFormat: "%m %-L %a", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "with headers %!-(INVALID_MODIFIER)L foo=bar\n", + }, + { + name: "invalid width modifier", + opts: HandlerOptions{HeaderFormat: "%m %43L %a", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "with headers %!43(INVALID_MODIFIER)L foo=bar\n", + }, + { + name: "invalid style modifier", + opts: HandlerOptions{HeaderFormat: "%m %(source)L %a", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "with headers %!((INVALID_MODIFIER)L foo=bar\n", + }, + { + name: "invalid key modifier", + opts: HandlerOptions{HeaderFormat: "%m %[source]L %a", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "with headers %![(INVALID_MODIFIER)L foo=bar\n", + }, + { + name: "invalid verb", + opts: HandlerOptions{HeaderFormat: "%l %x %m %a", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "INF %!x(INVALID_VERB) with headers foo=bar\n", + }, + { + name: "missing header name", + opts: HandlerOptions{HeaderFormat: "%m %h %a", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "with headers %!h(MISSING_HEADER_NAME) foo=bar\n", + }, + { + name: "missing closing bracket in header", + opts: HandlerOptions{HeaderFormat: "%m %[fooh > %a", NoColor: true}, + attrs: []slog.Attr{slog.String("foo", "bar")}, + want: "with headers %![fooh(MISSING_CLOSING_BRACKET) > foo=bar\n", + }, + { + name: "zero PC", + opts: HandlerOptions{HeaderFormat: "%l %[source]h > %m %a", NoColor: true, AddSource: true}, + recFunc: func(r *slog.Record) { + r.PC = 0 + }, + want: "INF > with headers\n", + }, + { + name: "level DEBUG-3", + opts: HandlerOptions{NoColor: true, HeaderFormat: "%l %L >"}, + recFunc: func(r *slog.Record) { + r.Level = slog.LevelDebug - 3 + }, + want: "DBG-3 DEBUG-3 >\n", + }, + { + name: "level DEBUG+1", + opts: HandlerOptions{NoColor: true, HeaderFormat: "%l %L >"}, + recFunc: func(r *slog.Record) { + r.Level = slog.LevelDebug + 1 + }, + want: "DBG+1 DEBUG+1 >\n", + }, + { + name: "level INFO+1", + opts: HandlerOptions{NoColor: true, HeaderFormat: "%l %L >"}, + recFunc: func(r *slog.Record) { + r.Level = slog.LevelInfo + 1 + }, + want: "INF+1 INFO+1 >\n", + }, + { + name: "level WARN +1", + opts: HandlerOptions{NoColor: true, HeaderFormat: "%l %L >"}, + recFunc: func(r *slog.Record) { + r.Level = slog.LevelWarn + 1 + }, + want: "WRN+1 WARN+1 >\n", + }, + { + name: "level ERROR+1", + opts: HandlerOptions{NoColor: true, HeaderFormat: "%l %L >"}, + recFunc: func(r *slog.Record) { + r.Level = slog.LevelError + 1 + }, + want: "ERR+1 ERROR+1 >\n", + }, + } + + for _, tt := range tests { + tt.msg = "with headers" + tt.pc = pc + tt.lvl = slog.LevelInfo + tt.time = testTime + t.Run(tt.name, tt.run) + } } -func TestHandler_Err(t *testing.T) { +type handlerTest struct { + name string + opts HandlerOptions + msg string + pc uintptr + lvl slog.Level + time time.Time + attrs []slog.Attr + handlerFunc func(h slog.Handler) slog.Handler + recFunc func(r *slog.Record) + want string +} + +func (ht handlerTest) run(t *testing.T) { + t.Helper() + buf := bytes.Buffer{} + var h slog.Handler = NewHandler(&buf, &ht.opts) + + rec := slog.NewRecord(ht.time, ht.lvl, ht.msg, ht.pc) + rec.AddAttrs(ht.attrs...) + + if ht.handlerFunc != nil { + h = ht.handlerFunc(h) + } + + if ht.recFunc != nil { + ht.recFunc(&rec) + } + + err := h.Handle(context.Background(), rec) + t.Log("format:", ht.opts.HeaderFormat) + t.Log(buf.String()) + AssertNoError(t, err) + AssertEqual(t, ht.want, buf.String()) +} + +func TestHandler_writerErr(t *testing.T) { w := writerFunc(func(b []byte) (int, error) { return 0, errors.New("nope") }) h := NewHandler(w, &HandlerOptions{NoColor: true}) rec := slog.NewRecord(time.Now(), slog.LevelInfo, "foobar", 0) @@ -279,158 +1407,174 @@ func TestHandler_Err(t *testing.T) { } func TestThemes(t *testing.T) { + pc, file, line, _ := runtime.Caller(0) + cwd, _ := os.Getwd() + file, _ = filepath.Rel(cwd, file) + sourceField := fmt.Sprintf("%s:%d", file, line) + + testTime := time.Date(2024, 01, 02, 15, 04, 05, 123456789, time.UTC) + for _, theme := range []Theme{ NewDefaultTheme(), NewBrightTheme(), } { - t.Run(theme.Name(), func(t *testing.T) { - level := slog.LevelInfo - rec := slog.Record{} - buf := bytes.Buffer{} - bufBytes := buf.Bytes() - now := time.Now() - timeFormat := time.Kitchen - index := -1 - toIndex := -1 - h := NewHandler(&buf, &HandlerOptions{ - AddSource: true, - TimeFormat: timeFormat, - Theme: theme, - }).WithAttrs([]slog.Attr{{Key: "pid", Value: slog.IntValue(37556)}}) - var pcs [1]uintptr - runtime.Callers(1, pcs[:]) - - checkANSIMod := func(t *testing.T, name string, ansiMod ANSIMod) { - t.Run(name, func(t *testing.T) { - index = bytes.IndexByte(bufBytes, '\x1b') - AssertNotEqual(t, -1, index) - toIndex = index + len(ansiMod) - AssertEqual(t, ansiMod, ANSIMod(bufBytes[index:toIndex])) - bufBytes = bufBytes[toIndex:] - index = bytes.IndexByte(bufBytes, '\x1b') - AssertNotEqual(t, -1, index) - toIndex = index + len(ResetMod) - AssertEqual(t, ResetMod, ANSIMod(bufBytes[index:toIndex])) - bufBytes = bufBytes[toIndex:] - }) + t.Run(theme.Name, func(t *testing.T) { + tests := []struct { + lvl slog.Level + msg string + args []any + wantLvlStr string + }{ + { + msg: "Access", + lvl: slog.LevelDebug - 1, + wantLvlStr: "DBG-1", + args: []any{ + "database", "myapp", "host", "localhost:4962", + }, + }, + { + msg: "Access", + lvl: slog.LevelDebug, + wantLvlStr: "DBG", + args: []any{ + "database", "myapp", "host", "localhost:4962", + }, + }, + { + msg: "Access", + lvl: slog.LevelDebug + 1, + wantLvlStr: "DBG+1", + args: []any{ + "database", "myapp", "host", "localhost:4962", + }, + }, + { + msg: "Starting listener", + lvl: slog.LevelInfo, + wantLvlStr: "INF", + args: []any{ + "listen", ":8080", + }, + }, + { + msg: "Access", + lvl: slog.LevelInfo + 1, + wantLvlStr: "INF+1", + args: []any{ + "method", "GET", "path", "/users", "resp_time", time.Millisecond * 10, + }, + }, + { + msg: "Slow request", + lvl: slog.LevelWarn, + wantLvlStr: "WRN", + args: []any{ + "method", "POST", "path", "/posts", "resp_time", time.Second * 532, + }, + }, + { + msg: "Slow request", + lvl: slog.LevelWarn + 1, + wantLvlStr: "WRN+1", + args: []any{ + "method", "POST", "path", "/posts", "resp_time", time.Second * 532, + }, + }, + { + msg: "Database connection lost", + lvl: slog.LevelError, + wantLvlStr: "ERR", + args: []any{ + "database", "myapp", "error", errors.New("connection reset by peer"), + }, + }, + { + msg: "Database connection lost", + lvl: slog.LevelError + 1, + wantLvlStr: "ERR+1", + args: []any{ + "database", "myapp", "error", errors.New("connection reset by peer"), + }, + }, } - checkLog := func(level slog.Level, attrCount int) { - t.Run("CheckLog_"+level.String(), func(t *testing.T) { - println("log: ", string(buf.Bytes())) + for _, tt := range tests { + // put together the expected log line - // Timestamp - if theme.Timestamp() != "" { - checkANSIMod(t, "Timestamp", theme.Timestamp()) - } + var levelStyle ANSIMod + switch { + case tt.lvl >= slog.LevelError: + levelStyle = theme.LevelError + case tt.lvl >= slog.LevelWarn: + levelStyle = theme.LevelWarn + case tt.lvl >= slog.LevelInfo: + levelStyle = theme.LevelInfo + default: + levelStyle = theme.LevelDebug + } - // Level - if theme.Level(level) != "" { - checkANSIMod(t, level.String(), theme.Level(level)) - } + var messageStyle ANSIMod + switch { + case tt.lvl >= slog.LevelInfo: + messageStyle = theme.Message + default: + messageStyle = theme.MessageDebug + } - // Source - if theme.Source() != "" { - checkANSIMod(t, "Source", theme.Source()) - checkANSIMod(t, "AttrKey", theme.AttrKey()) - } + withAttrs := []slog.Attr{{Key: "pid", Value: slog.IntValue(37556)}} + attrs := withAttrs + var rec slog.Record + rec.Add(tt.args...) + rec.Attrs(func(a slog.Attr) bool { + attrs = append(attrs, a) + return true + }) - // Message - if level >= slog.LevelInfo { - if theme.Message() != "" { - checkANSIMod(t, "Message", theme.Message()) - } + want := styled(testTime.Format(time.Kitchen), theme.Timestamp) + + " " + + styled(tt.wantLvlStr, levelStyle) + + " " + + styled("http", theme.Header) + + " " + + styled(sourceField, theme.Source) + + " " + + styled(">", theme.Header) + + " " + + styled(tt.msg, messageStyle) + + for _, attr := range attrs { + if attr.Key == "error" { + want += " " + + styled(attr.Key+"=", theme.AttrKey) + + styled(attr.Value.String(), theme.AttrValueError) } else { - if theme.MessageDebug() != "" { - checkANSIMod(t, "MessageDebug", theme.MessageDebug()) - } + want += " " + + styled(attr.Key+"=", theme.AttrKey) + + styled(attr.Value.String(), theme.AttrValue) } + } + want += "\n" - for i := 0; i < attrCount; i++ { - // AttrKey - if theme.AttrKey() != "" { - checkANSIMod(t, "AttrKey", theme.AttrKey()) - } - - // AttrValue - if theme.AttrValue() != "" { - checkANSIMod(t, "AttrValue", theme.AttrValue()) - } - } - }) + ht := handlerTest{ + opts: HandlerOptions{ + AddSource: true, + TimeFormat: time.Kitchen, + Theme: theme, + HeaderFormat: "%t %l %{%[logger]h %s >%} %m %a", + }, + attrs: append(withAttrs, slog.String("logger", "http")), + pc: pc, + time: testTime, + want: want, + lvl: tt.lvl, + msg: tt.msg, + recFunc: func(r *slog.Record) { + r.Add(tt.args...) + }, + } + t.Run(tt.wantLvlStr, ht.run) } - - buf.Reset() - level = slog.LevelDebug - 1 - rec = slog.NewRecord(now, level, "Access", pcs[0]) - rec.Add("database", "myapp", "host", "localhost:4962") - h.Handle(context.Background(), rec) - bufBytes = buf.Bytes() - checkLog(level, 3) - - buf.Reset() - level = slog.LevelDebug - rec = slog.NewRecord(now, level, "Access", pcs[0]) - rec.Add("database", "myapp", "host", "localhost:4962") - h.Handle(context.Background(), rec) - bufBytes = buf.Bytes() - checkLog(level, 3) - - buf.Reset() - level = slog.LevelDebug + 1 - rec = slog.NewRecord(now, level, "Access", pcs[0]) - rec.Add("database", "myapp", "host", "localhost:4962") - h.Handle(context.Background(), rec) - bufBytes = buf.Bytes() - checkLog(level, 3) - - buf.Reset() - level = slog.LevelInfo - rec = slog.NewRecord(now, level, "Starting listener", pcs[0]) - rec.Add("listen", ":8080") - h.Handle(context.Background(), rec) - bufBytes = buf.Bytes() - checkLog(level, 2) - - buf.Reset() - level = slog.LevelInfo + 1 - rec = slog.NewRecord(now, level, "Access", pcs[0]) - rec.Add("method", "GET", "path", "/users", "resp_time", time.Millisecond*10) - h.Handle(context.Background(), rec) - bufBytes = buf.Bytes() - checkLog(level, 4) - - buf.Reset() - level = slog.LevelWarn - rec = slog.NewRecord(now, level, "Slow request", pcs[0]) - rec.Add("method", "POST", "path", "/posts", "resp_time", time.Second*532) - h.Handle(context.Background(), rec) - bufBytes = buf.Bytes() - checkLog(level, 4) - - buf.Reset() - level = slog.LevelWarn + 1 - rec = slog.NewRecord(now, level, "Slow request", pcs[0]) - rec.Add("method", "POST", "path", "/posts", "resp_time", time.Second*532) - h.Handle(context.Background(), rec) - bufBytes = buf.Bytes() - checkLog(level, 4) - - buf.Reset() - level = slog.LevelError - rec = slog.NewRecord(now, level, "Database connection lost", pcs[0]) - rec.Add("database", "myapp", "error", errors.New("connection reset by peer")) - h.Handle(context.Background(), rec) - bufBytes = buf.Bytes() - checkLog(level, 3) - - buf.Reset() - level = slog.LevelError + 1 - rec = slog.NewRecord(now, level, "Database connection lost", pcs[0]) - rec.Add("database", "myapp", "error", errors.New("connection reset by peer")) - h.Handle(context.Background(), rec) - bufBytes = buf.Bytes() - checkLog(level, 3) }) } } diff --git a/internal/feature_flags.go b/internal/feature_flags.go new file mode 100644 index 0000000..b1e13b7 --- /dev/null +++ b/internal/feature_flags.go @@ -0,0 +1,13 @@ +package internal + +// FeatureFlagNewMultilineAttrs changes how attribute values containing newlines are handled. +// +// When true, multiline attributes are appended to the end of the log line, after everything in +// in the HeaderFormat, and the keys are printed on their own line, in the form "=== ===" +// +// When false, multiline attribute are printed right after the regular attributes, where ever that +// may be in the HeaderFormat. Keys are printed just like single-line attributes. +// +// In either case, multiline attributes will only be printed if the HeaderFormat contains an +// a %a directive. +var FeatureFlagNewMultilineAttrs = true diff --git a/theme.go b/theme.go index 8d1290f..9173e64 100644 --- a/theme.go +++ b/theme.go @@ -2,7 +2,6 @@ package console import ( "fmt" - "log/slog" ) type ANSIMod string @@ -59,93 +58,54 @@ func ToANSICode(modes ...int) ANSIMod { return ANSIMod("\x1b[" + s + "m") } -type Theme interface { - Name() string - Timestamp() ANSIMod - Source() ANSIMod - - Message() ANSIMod - MessageDebug() ANSIMod - AttrKey() ANSIMod - AttrValue() ANSIMod - AttrValueError() ANSIMod - LevelError() ANSIMod - LevelWarn() ANSIMod - LevelInfo() ANSIMod - LevelDebug() ANSIMod - Level(level slog.Level) ANSIMod -} - -type ThemeDef struct { - name string - timestamp ANSIMod - source ANSIMod - message ANSIMod - messageDebug ANSIMod - attrKey ANSIMod - attrValue ANSIMod - attrValueError ANSIMod - levelError ANSIMod - levelWarn ANSIMod - levelInfo ANSIMod - levelDebug ANSIMod -} - -func (t ThemeDef) Name() string { return t.name } -func (t ThemeDef) Timestamp() ANSIMod { return t.timestamp } -func (t ThemeDef) Source() ANSIMod { return t.source } -func (t ThemeDef) Message() ANSIMod { return t.message } -func (t ThemeDef) MessageDebug() ANSIMod { return t.messageDebug } -func (t ThemeDef) AttrKey() ANSIMod { return t.attrKey } -func (t ThemeDef) AttrValue() ANSIMod { return t.attrValue } -func (t ThemeDef) AttrValueError() ANSIMod { return t.attrValueError } -func (t ThemeDef) LevelError() ANSIMod { return t.levelError } -func (t ThemeDef) LevelWarn() ANSIMod { return t.levelWarn } -func (t ThemeDef) LevelInfo() ANSIMod { return t.levelInfo } -func (t ThemeDef) LevelDebug() ANSIMod { return t.levelDebug } -func (t ThemeDef) Level(level slog.Level) ANSIMod { - switch { - case level >= slog.LevelError: - return t.LevelError() - case level >= slog.LevelWarn: - return t.LevelWarn() - case level >= slog.LevelInfo: - return t.LevelInfo() - default: - return t.LevelDebug() - } +type Theme struct { + Name string + Timestamp ANSIMod + Header ANSIMod + Source ANSIMod + Message ANSIMod + MessageDebug ANSIMod + AttrKey ANSIMod + AttrValue ANSIMod + AttrValueError ANSIMod + LevelError ANSIMod + LevelWarn ANSIMod + LevelInfo ANSIMod + LevelDebug ANSIMod } func NewDefaultTheme() Theme { - return ThemeDef{ - name: "Default", - timestamp: ToANSICode(BrightBlack), - source: ToANSICode(Bold, BrightBlack), - message: ToANSICode(Bold), - messageDebug: ToANSICode(), - attrKey: ToANSICode(Cyan), - attrValue: ToANSICode(), - attrValueError: ToANSICode(Bold, Red), - levelError: ToANSICode(Red), - levelWarn: ToANSICode(Yellow), - levelInfo: ToANSICode(Green), - levelDebug: ToANSICode(), + return Theme{ + Name: "Default", + Timestamp: ToANSICode(Faint), + Header: ToANSICode(Faint, Bold), + Source: ToANSICode(BrightBlack, Italic), + Message: ToANSICode(Bold), + MessageDebug: ToANSICode(Bold), + AttrKey: ToANSICode(Faint, Green), + AttrValue: ToANSICode(), + AttrValueError: ToANSICode(Bold, Red), + LevelError: ToANSICode(Red), + LevelWarn: ToANSICode(Yellow), + LevelInfo: ToANSICode(Cyan), + LevelDebug: ToANSICode(BrightMagenta), } } func NewBrightTheme() Theme { - return ThemeDef{ - name: "Bright", - timestamp: ToANSICode(Gray), - source: ToANSICode(Bold, Gray), - message: ToANSICode(Bold, White), - messageDebug: ToANSICode(), - attrKey: ToANSICode(BrightCyan), - attrValue: ToANSICode(), - attrValueError: ToANSICode(Bold, BrightRed), - levelError: ToANSICode(BrightRed), - levelWarn: ToANSICode(BrightYellow), - levelInfo: ToANSICode(BrightGreen), - levelDebug: ToANSICode(), + return Theme{ + Name: "Bright", + Timestamp: ToANSICode(Gray), + Header: ToANSICode(Bold, Gray), + Source: ToANSICode(Gray, Bold, Italic), + Message: ToANSICode(Bold, White), + MessageDebug: ToANSICode(), + AttrKey: ToANSICode(BrightCyan), + AttrValue: ToANSICode(), + AttrValueError: ToANSICode(Bold, BrightRed), + LevelError: ToANSICode(BrightRed), + LevelWarn: ToANSICode(BrightYellow), + LevelInfo: ToANSICode(BrightGreen), + LevelDebug: ToANSICode(), } } diff --git a/utils_test.go b/utils_test.go index abeb4dc..731ef79 100644 --- a/utils_test.go +++ b/utils_test.go @@ -16,7 +16,7 @@ func AssertZero[E comparable](t *testing.T, v E) { func AssertEqual[E comparable](t *testing.T, expected, value E) { t.Helper() if expected != value { - t.Errorf("expected %v, got %v", expected, value) + t.Errorf("\nexpected: %v\n got: %v", expected, value) } }