From f8d173bcec714476506f0513b6b7e97a756d891e Mon Sep 17 00:00:00 2001 From: Benjamin Bengfort Date: Fri, 27 Mar 2026 15:59:00 -0500 Subject: [PATCH 01/18] [FEAT] Console Log --- rlog/console/color.go | 29 +++++++ rlog/console/console.go | 147 +++++++++++++++++++++++++++++++++++ rlog/console/console_test.go | 1 + rlog/console/options.go | 19 +++++ 4 files changed, 196 insertions(+) create mode 100644 rlog/console/color.go create mode 100644 rlog/console/console.go create mode 100644 rlog/console/console_test.go create mode 100644 rlog/console/options.go diff --git a/rlog/console/color.go b/rlog/console/color.go new file mode 100644 index 0000000..d9368ad --- /dev/null +++ b/rlog/console/color.go @@ -0,0 +1,29 @@ +package console + +import ( + "fmt" + "io" +) + +const ( + black uint = 30 + red = 31 + green = 32 + yellow = 33 + blue = 34 + magenta = 35 + cyan = 36 + lightGray = 37 + darkGray = 90 + lightRed = 91 + lightGreen = 92 + lightYellow = 93 + lightBlue = 94 + lightMagenta = 95 + lightCyan = 96 + white = 97 +) + +func colorize(w io.Writer, color uint8, text string) { + fmt.Fprintf(w, "\033[%dm%s\033[0m", color, text) +} diff --git a/rlog/console/console.go b/rlog/console/console.go new file mode 100644 index 0000000..982a4a9 --- /dev/null +++ b/rlog/console/console.go @@ -0,0 +1,147 @@ +// Package console provides a console handler for the rlog package that pretty prints +// colored text logs to stdout. It is a wrapper around the slog.Handler interface. +// +// NOTE: this should only be used for testing and development. +package console + +import ( + "bytes" + "context" + "encoding/json" + "fmt" + "io" + "log/slog" + "sync" + + "go.rtnl.ai/x/rlog" +) + +const ( + timeFormat = "[15:04:05.000]" +) + +type Handler struct { + slog.Handler + w io.Writer + mu *sync.Mutex + opts Options +} + +func New(w io.Writer, opts *Options) *Handler { + if opts == nil { + opts = &Options{} + } + + return &Handler{ + Handler: slog.NewTextHandler(w, opts.HandlerOptions), + w: w, + opts: *opts, + mu: &sync.Mutex{}, + } +} + +var _ slog.Handler = (*Handler)(nil) + +func (h *Handler) WithAttrs(attrs []slog.Attr) slog.Handler { + return &Handler{ + Handler: h.Handler.WithAttrs(attrs), + w: h.w, + mu: h.mu, // mutex shared by all clones of this handler + opts: h.opts, + } +} + +func (h *Handler) WithGroup(name string) slog.Handler { + return &Handler{ + Handler: h.Handler.WithGroup(name), + w: h.w, + mu: h.mu, // mutex shared by all clones of this handler + opts: h.opts, + } +} + +func (h *Handler) Handle(ctx context.Context, r slog.Record) error { + // Write to a buffer first to avoid race conditions with the writer. + // NOTE: slog uses an internal pool-allocated bytes buffer for performance. + // Because we're allocating a new buffer here, this handler should not be used in + // performance intensive applications. + var buf bytes.Buffer + + // Print the timestamp. + if h.opts.NoColor { + fmt.Fprint(&buf, r.Time.Format(timeFormat)) + } else { + colorize(&buf, lightGray, timeFormat) + } + + // Space separator between timestamp and level. + buf.WriteRune(' ') + + // Print the level. + level := r.Level.String() + ":" + if h.opts.NoColor { + fmt.Fprint(&buf, level) + } else { + switch r.Level { + case rlog.LevelTrace: + colorize(&buf, lightGray, level) + case slog.LevelDebug: + colorize(&buf, cyan, level) + case slog.LevelInfo: + colorize(&buf, lightGreen, level) + case slog.LevelWarn: + colorize(&buf, lightYellow, level) + case slog.LevelError: + colorize(&buf, lightRed, level) + case rlog.LevelFatal: + colorize(&buf, red, level) + case rlog.LevelPanic: + colorize(&buf, red, level) + default: + fmt.Fprint(&buf, level) + } + } + + // Space separator between level and message. + buf.WriteRune(' ') + + // Print the message. + if h.opts.NoColor { + fmt.Fprint(&buf, r.Message) + } else { + colorize(&buf, white, r.Message) + } + + if !h.opts.NoJSON { + // Space separator between message and JSON dictionary. + buf.WriteRune(' ') + + // Gather the attributes. + attrs := make(map[string]any) + r.Attrs(func(a slog.Attr) bool { + // Skip the level, message, and time keys. + if a.Key == slog.LevelKey || a.Key == slog.MessageKey || a.Key == slog.TimeKey { + return true + } + attrs[a.Key] = a.Value.Any() + return true + }) + + // Print the JSON dictionary of attributes. + encoder := json.NewEncoder(&buf) + if h.opts.IndentJSON { + encoder.SetIndent("", " ") + } + if err := encoder.Encode(attrs); err != nil { + return err + } + } + + // Lock this mutex including all handler clones so that we can write to the writer safely. + h.mu.Lock() + defer h.mu.Unlock() + if _, err := h.w.Write(buf.Bytes()); err != nil { + return err + } + return nil +} diff --git a/rlog/console/console_test.go b/rlog/console/console_test.go new file mode 100644 index 0000000..d1f2f9c --- /dev/null +++ b/rlog/console/console_test.go @@ -0,0 +1 @@ +package console_test diff --git a/rlog/console/options.go b/rlog/console/options.go new file mode 100644 index 0000000..12d7074 --- /dev/null +++ b/rlog/console/options.go @@ -0,0 +1,19 @@ +package console + +import "log/slog" + +// Options are used for the [console.Handler] a nil or zero valued Options consists +// entirely of default values. +type Options struct { + // The [slog.HandlerOptions] to use for the [console.Handler]. + *slog.HandlerOptions + + // Marking true causes the handler to format the logs without terminal colors. + NoColor bool + + // Marking true causes the handler to indent the JSON dictionary on multiple lines. + IndentJSON bool + + // Marking true causes the handler to format the logs without JSON dictionary of attributes. + NoJSON bool +} From 6b09faba29f155cb1a05aef112c6206dcf51097e Mon Sep 17 00:00:00 2001 From: Benjamin Bengfort Date: Fri, 27 Mar 2026 16:25:15 -0500 Subject: [PATCH 02/18] add tests --- rlog/console/color.go | 23 ++----- rlog/console/console.go | 4 +- rlog/console/console_test.go | 130 +++++++++++++++++++++++++++++++++++ 3 files changed, 140 insertions(+), 17 deletions(-) diff --git a/rlog/console/color.go b/rlog/console/color.go index d9368ad..baf546f 100644 --- a/rlog/console/color.go +++ b/rlog/console/color.go @@ -6,22 +6,13 @@ import ( ) const ( - black uint = 30 - red = 31 - green = 32 - yellow = 33 - blue = 34 - magenta = 35 - cyan = 36 - lightGray = 37 - darkGray = 90 - lightRed = 91 - lightGreen = 92 - lightYellow = 93 - lightBlue = 94 - lightMagenta = 95 - lightCyan = 96 - white = 97 + red = 31 + cyan = 36 + lightGray = 37 + lightRed = 91 + lightGreen = 92 + lightYellow = 93 + white = 97 ) func colorize(w io.Writer, color uint8, text string) { diff --git a/rlog/console/console.go b/rlog/console/console.go index 982a4a9..9edab39 100644 --- a/rlog/console/console.go +++ b/rlog/console/console.go @@ -71,7 +71,7 @@ func (h *Handler) Handle(ctx context.Context, r slog.Record) error { if h.opts.NoColor { fmt.Fprint(&buf, r.Time.Format(timeFormat)) } else { - colorize(&buf, lightGray, timeFormat) + colorize(&buf, lightGray, r.Time.Format(timeFormat)) } // Space separator between timestamp and level. @@ -135,6 +135,8 @@ func (h *Handler) Handle(ctx context.Context, r slog.Record) error { if err := encoder.Encode(attrs); err != nil { return err } + } else { + buf.WriteRune('\n') } // Lock this mutex including all handler clones so that we can write to the writer safely. diff --git a/rlog/console/console_test.go b/rlog/console/console_test.go index d1f2f9c..4dc74c1 100644 --- a/rlog/console/console_test.go +++ b/rlog/console/console_test.go @@ -1 +1,131 @@ package console_test + +import ( + "bytes" + "context" + "log/slog" + "testing" + "testing/synctest" + + "go.rtnl.ai/x/assert" + "go.rtnl.ai/x/rlog" + "go.rtnl.ai/x/rlog/console" +) + +func TestHandler(t *testing.T) { + testCases := []struct { + name string + opts *console.Options + want []byte + }{ + { + name: "Default", + opts: nil, + want: []byte("\x1b[37m[18:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {}\n"), + }, + { + name: "NoColor", + opts: &console.Options{NoColor: true}, + want: []byte("[18:00:00.000] INFO: info {}\n[18:00:00.000] WARN: warning {}\n[18:00:00.000] ERROR: error {}\n"), + }, + { + name: "NoJSON", + opts: &console.Options{NoJSON: true}, + want: []byte("\x1b[37m[18:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m\n"), + }, + { + name: "Plain", + opts: &console.Options{NoColor: true, NoJSON: true}, + want: []byte("[18:00:00.000] INFO: info\n[18:00:00.000] WARN: warning\n[18:00:00.000] ERROR: error\n"), + }, + { + name: "IndentJSON", + opts: &console.Options{IndentJSON: true}, + want: []byte("\x1b[37m[18:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {}\n"), + }, + { + name: "Trace", + opts: &console.Options{HandlerOptions: &slog.HandlerOptions{Level: rlog.LevelTrace}}, + want: []byte("\x1b[37m[18:00:00.000]\x1b[0m \x1b[37mDEBUG-4:\x1b[0m \x1b[97mtracing\x1b[0m {}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[36mDEBUG:\x1b[0m \x1b[97mdebugging\x1b[0m {}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {}\n"), + }, + } + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + var buf bytes.Buffer + logger := rlog.New(slog.New(console.New(&buf, tc.opts))) + + logger.Trace("tracing") + logger.Debug("debugging") + logger.Info("info") + logger.Warn("warning") + logger.Error("error") + + assert.True(t, bytes.Equal(buf.Bytes(), tc.want)) + }) + }) + } +} + +func TestHandler_WithAttrs(t *testing.T) { + testCases := []struct { + name string + opts *console.Options + want []byte + }{ + { + name: "Default", + opts: nil, + want: []byte("\x1b[37m[18:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\"foo\":\"bar\",\"user\":\"alice\"}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\"code\":404,\"error\":\"not found\"}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\"code\":400,\"error\":\"uncapped jar\"}\n"), + }, + { + name: "NoColor", + opts: &console.Options{NoColor: true}, + want: []byte("[18:00:00.000] INFO: info {\"foo\":\"bar\",\"user\":\"alice\"}\n[18:00:00.000] WARN: warning {\"code\":404,\"error\":\"not found\"}\n[18:00:00.000] ERROR: error {\"code\":400,\"error\":\"uncapped jar\"}\n"), + }, + { + name: "NoJSON", + opts: &console.Options{NoJSON: true}, + want: []byte("\x1b[37m[18:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m\n"), + }, + { + name: "Plain", + opts: &console.Options{NoColor: true, NoJSON: true}, + want: []byte("[18:00:00.000] INFO: info\n[18:00:00.000] WARN: warning\n[18:00:00.000] ERROR: error\n"), + }, + { + name: "IndentJSON", + opts: &console.Options{IndentJSON: true}, + want: []byte("\x1b[37m[18:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\n \"foo\": \"bar\",\n \"user\": \"alice\"\n}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\n \"code\": 404,\n \"error\": \"not found\"\n}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\n \"code\": 400,\n \"error\": \"uncapped jar\"\n}\n"), + }, + { + name: "IndentJSONNoColor", + opts: &console.Options{IndentJSON: true, NoColor: true}, + want: []byte("[18:00:00.000] INFO: info {\n \"foo\": \"bar\",\n \"user\": \"alice\"\n}\n[18:00:00.000] WARN: warning {\n \"code\": 404,\n \"error\": \"not found\"\n}\n[18:00:00.000] ERROR: error {\n \"code\": 400,\n \"error\": \"uncapped jar\"\n}\n"), + }, + { + name: "Trace", + opts: &console.Options{HandlerOptions: &slog.HandlerOptions{Level: rlog.LevelTrace}}, + want: []byte("\x1b[37m[18:00:00.000]\x1b[0m \x1b[37mDEBUG-4:\x1b[0m \x1b[97mtracing\x1b[0m {\"foo\":\"bar\"}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[36mDEBUG:\x1b[0m \x1b[97mdebugging\x1b[0m {\"foo\":\"bar\",\"user\":\"bob\"}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\"foo\":\"bar\",\"user\":\"alice\"}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\"code\":404,\"error\":\"not found\"}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\"code\":400,\"error\":\"uncapped jar\"}\n"), + }, + } + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + var buf bytes.Buffer + logger := rlog.New(slog.New(console.New(&buf, tc.opts))) + ctx := context.Background() + + logger.TraceAttrs(ctx, "tracing", slog.String("foo", "bar")) + logger.DebugAttrs(ctx, "debugging", slog.String("foo", "bar"), slog.String("user", "bob")) + logger.InfoAttrs(ctx, "info", slog.String("foo", "bar"), slog.String("user", "alice")) + logger.WarnAttrs(ctx, "warning", slog.String("error", "not found"), slog.Int("code", 404)) + logger.ErrorAttrs(ctx, "error", slog.String("error", "uncapped jar"), slog.Int("code", 400)) + + assert.True(t, bytes.Equal(buf.Bytes(), tc.want)) + }) + }) + } +} From 8fd647de25dc89d680f961f4572d9412bd3c4a32 Mon Sep 17 00:00:00 2001 From: Chris Okuda Date: Sat, 28 Mar 2026 11:37:37 -1000 Subject: [PATCH 03/18] move the test helpers into a rlog/testing package --- rlog/fanout_test.go | 3 ++- rlog/{ => testing}/testing.go | 43 +++++++++++++++++++++++++++--- rlog/{ => testing}/testing_test.go | 24 ++++++++--------- 3 files changed, 54 insertions(+), 16 deletions(-) rename rlog/{ => testing}/testing.go (81%) rename rlog/{ => testing}/testing_test.go (81%) diff --git a/rlog/fanout_test.go b/rlog/fanout_test.go index 1c7d8ec..2cca750 100644 --- a/rlog/fanout_test.go +++ b/rlog/fanout_test.go @@ -11,6 +11,7 @@ import ( "go.rtnl.ai/x/assert" "go.rtnl.ai/x/rlog" + rlogtesting "go.rtnl.ai/x/rlog/testing" ) // Each sink receives the same logical record when levels allow. @@ -85,7 +86,7 @@ func TestFanOut_slogtest_singleChild(t *testing.T) { if line == "" { continue } - m, e := rlog.ParseJSONLine(line) + m, e := rlogtesting.ParseJSONLine(line) assert.Ok(t, e) maps = append(maps, m) } diff --git a/rlog/testing.go b/rlog/testing/testing.go similarity index 81% rename from rlog/testing.go rename to rlog/testing/testing.go index e41eda1..fe95846 100644 --- a/rlog/testing.go +++ b/rlog/testing/testing.go @@ -1,4 +1,39 @@ -package rlog +// Package testing provides helpers for testing slog handlers and other +// logging-related functionality. +// +// Example usage: +// +// func TestSomething(t *testing.T) { +// // Captures slog.Record and JSON lines, also outputting to the test log +// h := NewCapturingTestHandler(t) +// +// // Can use with slog directly, or wrap with rlog.New to get rlog.Logger. +// slogLogger := slog.New(h) +// slogLogger.Info("hello", "k", "v") +// rlogLogger := rlog.New(slogLogger) +// rlogLogger.Trace("traced", "k2", "v2") +// +// // Parse the JSON line into a map for assertions +// lines := h.Lines() +// m, err := ParseJSONLine(lines[0]) +// assert.Ok(t, err) +// assert.Equal(t, "INFO", m["level"]) +// assert.Equal(t, "hello", m["msg"]) +// assert.Equal(t, "v", m["k"]) +// +// // MustParseJSONLine panics on error +// m2 := MustParseJSONLine(lines[0]) +// assert.Equal(t, m, m2) +// +// // Get a mutex-locked snapshot of records and lines +// records, err := h.RecordsAndLines() +// assert.Ok(t, err) +// assert.Equal(t, 2, len(records)) +// assert.Equal(t, "TRACE", records[1].Level()) +// assert.Equal(t, "traced", records[1].Message()) +// assert.Equal(t, "v2", records[1].Attrs()[0].Value.String()) +// } +package testing import ( "bytes" @@ -9,11 +44,13 @@ import ( "strings" "sync" "testing" + + "go.rtnl.ai/x/rlog" ) // capturingJSONOpts is reused by [CapturingTestHandler.Handle] so every log line -// does not rebuild [MergeWithCustomLevels](nil) (closure + [slog.HandlerOptions] escape). -var capturingJSONOpts = MergeWithCustomLevels(nil) +// does not rebuild [rlog.MergeWithCustomLevels](nil) (closure + [slog.HandlerOptions] escape). +var capturingJSONOpts = rlog.MergeWithCustomLevels(nil) // captureState holds lines and records shared by all derived handlers from the same root. type captureState struct { diff --git a/rlog/testing_test.go b/rlog/testing/testing_test.go similarity index 81% rename from rlog/testing_test.go rename to rlog/testing/testing_test.go index 64bdf87..4c4ac35 100644 --- a/rlog/testing_test.go +++ b/rlog/testing/testing_test.go @@ -1,4 +1,4 @@ -package rlog_test +package testing_test import ( "context" @@ -11,12 +11,12 @@ import ( "time" "go.rtnl.ai/x/assert" - "go.rtnl.ai/x/rlog" + rlogtesting "go.rtnl.ai/x/rlog/testing" ) // CapturingTestHandler should pass the standard slog handler tests. func TestCapturingTestHandler_slogtest(t *testing.T) { - cap := rlog.NewCapturingTestHandler(nil) + cap := rlogtesting.NewCapturingTestHandler(nil) err := slogtest.TestHandler(cap, func() []map[string]any { maps, err := cap.ResultMaps() assert.Ok(t, err) @@ -27,15 +27,15 @@ func TestCapturingTestHandler_slogtest(t *testing.T) { // Groups nest attrs in JSON output and ResultMaps sees nested maps. func TestCapturingTestHandler_groupNesting(t *testing.T) { - h := rlog.NewCapturingTestHandler(nil).WithGroup("g").(*rlog.CapturingTestHandler) - h = h.WithAttrs([]slog.Attr{slog.String("inside", "yes")}).(*rlog.CapturingTestHandler) + h := rlogtesting.NewCapturingTestHandler(nil).WithGroup("g").(*rlogtesting.CapturingTestHandler) + h = h.WithAttrs([]slog.Attr{slog.String("inside", "yes")}).(*rlogtesting.CapturingTestHandler) ctx := context.Background() assert.Ok(t, h.Handle(ctx, slog.NewRecord(time.Now(), slog.LevelInfo, "hi", 0))) lines := h.Lines() assert.Equal(t, 1, len(lines)) - m := rlog.MustParseJSONLine(lines[0]) + m := rlogtesting.MustParseJSONLine(lines[0]) g, ok := m["g"].(map[string]any) assert.True(t, ok) assert.Equal(t, "yes", g["inside"]) @@ -44,17 +44,17 @@ func TestCapturingTestHandler_groupNesting(t *testing.T) { // ParseJSONLine and MustParseJSONLine round-trip a simple object. func TestParseJSONLine_helpers(t *testing.T) { const line = `{"level":"INFO","msg":"x","k":1}` - m, err := rlog.ParseJSONLine(line) + m, err := rlogtesting.ParseJSONLine(line) assert.Ok(t, err) assert.Equal(t, "INFO", m["level"]) assert.Equal(t, float64(1), m["k"]) - assert.Equal(t, m, rlog.MustParseJSONLine(line)) + assert.Equal(t, m, rlogtesting.MustParseJSONLine(line)) } // NewCapturingTestHandler links to [testing.TB] (only *testing.T / B / F satisfy TB outside stdlib). // Derived handlers still share capture state; slogtest exercises WithAttrs/WithGroup with tb set. func TestCapturingTestHandler_slogtest_withTB(t *testing.T) { - cap := rlog.NewCapturingTestHandler(t) + cap := rlogtesting.NewCapturingTestHandler(t) err := slogtest.TestHandler(cap, func() []map[string]any { maps, err := cap.ResultMaps() assert.Ok(t, err) @@ -65,7 +65,7 @@ func TestCapturingTestHandler_slogtest_withTB(t *testing.T) { // Concurrent Handle calls must keep the same index aligned in records and lines. func TestCapturingTestHandler_concurrentHandle_recordsMatchLines(t *testing.T) { - h := rlog.NewCapturingTestHandler(nil) + h := rlogtesting.NewCapturingTestHandler(nil) ctx := context.Background() const n = 64 var wg sync.WaitGroup @@ -89,11 +89,11 @@ func TestCapturingTestHandler_concurrentHandle_recordsMatchLines(t *testing.T) { // Derived handlers share the same capture buffers. func TestCapturingTestHandler_derivedSharesLines(t *testing.T) { - h := rlog.NewCapturingTestHandler(nil) + h := rlogtesting.NewCapturingTestHandler(nil) ctx := context.Background() assert.Ok(t, h.Handle(ctx, slog.NewRecord(time.Now(), slog.LevelInfo, "one", 0))) - h2 := h.WithAttrs([]slog.Attr{slog.String("k", "v")}).(*rlog.CapturingTestHandler) + h2 := h.WithAttrs([]slog.Attr{slog.String("k", "v")}).(*rlogtesting.CapturingTestHandler) assert.Ok(t, h2.Handle(ctx, slog.NewRecord(time.Now(), slog.LevelWarn, "two", 0))) lines := h.Lines() From 00a0dd570e118fee59e3c58f90f1a970a774d7b9 Mon Sep 17 00:00:00 2001 From: Chris Okuda Date: Sat, 28 Mar 2026 12:39:50 -1000 Subject: [PATCH 04/18] update to get the tests working as-is; we're using a new option to do so for now --- rlog/console/console.go | 75 ++++++++++++++++++++++++++++++++++-- rlog/console/console_test.go | 46 ++++++++++++++-------- rlog/console/options.go | 3 ++ 3 files changed, 104 insertions(+), 20 deletions(-) diff --git a/rlog/console/console.go b/rlog/console/console.go index 9edab39..93772ae 100644 --- a/rlog/console/console.go +++ b/rlog/console/console.go @@ -68,10 +68,14 @@ func (h *Handler) Handle(ctx context.Context, r slog.Record) error { var buf bytes.Buffer // Print the timestamp. + tm := r.Time + if h.opts.UTCTime { + tm = tm.UTC() + } if h.opts.NoColor { - fmt.Fprint(&buf, r.Time.Format(timeFormat)) + fmt.Fprint(&buf, tm.Format(timeFormat)) } else { - colorize(&buf, lightGray, r.Time.Format(timeFormat)) + colorize(&buf, lightGray, tm.Format(timeFormat)) } // Space separator between timestamp and level. @@ -123,7 +127,7 @@ func (h *Handler) Handle(ctx context.Context, r slog.Record) error { if a.Key == slog.LevelKey || a.Key == slog.MessageKey || a.Key == slog.TimeKey { return true } - attrs[a.Key] = a.Value.Any() + addAttr(attrs, a) return true }) @@ -147,3 +151,68 @@ func (h *Handler) Handle(ctx context.Context, r slog.Record) error { } return nil } + +// addAttr adds an attribute to the map, capturing groups properly. +func addAttr(attrs map[string]any, a slog.Attr) { + // Resolve the value of the attribute. + a.Value = a.Value.Resolve() + if a.Equal(slog.Attr{}) { + return + } + + // Add the attribute to the map. + switch a.Value.Kind() { + case slog.KindGroup: + // Group values carry nested attrs (e.g. slog.Group("db", ...)). + gattrs := a.Value.Group() + if len(gattrs) == 0 { + return + } + if a.Key != "" { + // Named group: nest under this key as a JSON object, merging with any + // prior attrs already stored for the same key. + var sub map[string]any + if existing, ok := attrs[a.Key].(map[string]any); ok { + sub = existing + } else { + sub = make(map[string]any) + attrs[a.Key] = sub + } + + for _, ga := range gattrs { + addAttr(sub, ga) + } + } else { + // Anonymous / inline group: add members at the current map level (no extra nesting). + for _, ga := range gattrs { + addAttr(attrs, ga) + } + } + default: + attrs[a.Key] = slogValueToJSON(a.Value) + } +} + +// slogValueToJSON returns a value suitable for encoding/json from a resolved slog.Value. +func slogValueToJSON(v slog.Value) any { + switch v.Kind() { + case slog.KindString: + return v.String() + case slog.KindInt64: + return v.Int64() + case slog.KindUint64: + return v.Uint64() + case slog.KindFloat64: + return v.Float64() + case slog.KindBool: + return v.Bool() + case slog.KindTime: + return v.Time() + case slog.KindDuration: + return v.Duration() + case slog.KindAny: + return v.Any() + default: + return v.String() + } +} diff --git a/rlog/console/console_test.go b/rlog/console/console_test.go index 4dc74c1..77663e1 100644 --- a/rlog/console/console_test.go +++ b/rlog/console/console_test.go @@ -21,32 +21,32 @@ func TestHandler(t *testing.T) { { name: "Default", opts: nil, - want: []byte("\x1b[37m[18:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {}\n"), + want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {}\n"), }, { name: "NoColor", opts: &console.Options{NoColor: true}, - want: []byte("[18:00:00.000] INFO: info {}\n[18:00:00.000] WARN: warning {}\n[18:00:00.000] ERROR: error {}\n"), + want: []byte("[00:00:00.000] INFO: info {}\n[00:00:00.000] WARN: warning {}\n[00:00:00.000] ERROR: error {}\n"), }, { name: "NoJSON", opts: &console.Options{NoJSON: true}, - want: []byte("\x1b[37m[18:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m\n"), + want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m\n"), }, { name: "Plain", opts: &console.Options{NoColor: true, NoJSON: true}, - want: []byte("[18:00:00.000] INFO: info\n[18:00:00.000] WARN: warning\n[18:00:00.000] ERROR: error\n"), + want: []byte("[00:00:00.000] INFO: info\n[00:00:00.000] WARN: warning\n[00:00:00.000] ERROR: error\n"), }, { name: "IndentJSON", opts: &console.Options{IndentJSON: true}, - want: []byte("\x1b[37m[18:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {}\n"), + want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {}\n"), }, { name: "Trace", opts: &console.Options{HandlerOptions: &slog.HandlerOptions{Level: rlog.LevelTrace}}, - want: []byte("\x1b[37m[18:00:00.000]\x1b[0m \x1b[37mDEBUG-4:\x1b[0m \x1b[97mtracing\x1b[0m {}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[36mDEBUG:\x1b[0m \x1b[97mdebugging\x1b[0m {}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {}\n"), + want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[37mDEBUG-4:\x1b[0m \x1b[97mtracing\x1b[0m {}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[36mDEBUG:\x1b[0m \x1b[97mdebugging\x1b[0m {}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {}\n"), }, } @@ -54,7 +54,12 @@ func TestHandler(t *testing.T) { t.Run(tc.name, func(t *testing.T) { synctest.Test(t, func(t *testing.T) { var buf bytes.Buffer - logger := rlog.New(slog.New(console.New(&buf, tc.opts))) + opts := tc.opts + if opts == nil { + opts = &console.Options{} + } + opts.UTCTime = true + logger := rlog.New(slog.New(console.New(&buf, opts))) logger.Trace("tracing") logger.Debug("debugging") @@ -62,7 +67,7 @@ func TestHandler(t *testing.T) { logger.Warn("warning") logger.Error("error") - assert.True(t, bytes.Equal(buf.Bytes(), tc.want)) + assert.True(t, bytes.Equal(buf.Bytes(), tc.want), "got:\n%q \nwant:\n%q", buf.Bytes(), tc.want) }) }) } @@ -77,37 +82,37 @@ func TestHandler_WithAttrs(t *testing.T) { { name: "Default", opts: nil, - want: []byte("\x1b[37m[18:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\"foo\":\"bar\",\"user\":\"alice\"}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\"code\":404,\"error\":\"not found\"}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\"code\":400,\"error\":\"uncapped jar\"}\n"), + want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\"foo\":\"bar\",\"user\":\"alice\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\"code\":404,\"error\":\"not found\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\"code\":400,\"error\":\"uncapped jar\"}\n"), }, { name: "NoColor", opts: &console.Options{NoColor: true}, - want: []byte("[18:00:00.000] INFO: info {\"foo\":\"bar\",\"user\":\"alice\"}\n[18:00:00.000] WARN: warning {\"code\":404,\"error\":\"not found\"}\n[18:00:00.000] ERROR: error {\"code\":400,\"error\":\"uncapped jar\"}\n"), + want: []byte("[00:00:00.000] INFO: info {\"foo\":\"bar\",\"user\":\"alice\"}\n[00:00:00.000] WARN: warning {\"code\":404,\"error\":\"not found\"}\n[00:00:00.000] ERROR: error {\"code\":400,\"error\":\"uncapped jar\"}\n"), }, { name: "NoJSON", opts: &console.Options{NoJSON: true}, - want: []byte("\x1b[37m[18:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m\n"), + want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m\n"), }, { name: "Plain", opts: &console.Options{NoColor: true, NoJSON: true}, - want: []byte("[18:00:00.000] INFO: info\n[18:00:00.000] WARN: warning\n[18:00:00.000] ERROR: error\n"), + want: []byte("[00:00:00.000] INFO: info\n[00:00:00.000] WARN: warning\n[00:00:00.000] ERROR: error\n"), }, { name: "IndentJSON", opts: &console.Options{IndentJSON: true}, - want: []byte("\x1b[37m[18:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\n \"foo\": \"bar\",\n \"user\": \"alice\"\n}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\n \"code\": 404,\n \"error\": \"not found\"\n}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\n \"code\": 400,\n \"error\": \"uncapped jar\"\n}\n"), + want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\n \"foo\": \"bar\",\n \"user\": \"alice\"\n}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\n \"code\": 404,\n \"error\": \"not found\"\n}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\n \"code\": 400,\n \"error\": \"uncapped jar\"\n}\n"), }, { name: "IndentJSONNoColor", opts: &console.Options{IndentJSON: true, NoColor: true}, - want: []byte("[18:00:00.000] INFO: info {\n \"foo\": \"bar\",\n \"user\": \"alice\"\n}\n[18:00:00.000] WARN: warning {\n \"code\": 404,\n \"error\": \"not found\"\n}\n[18:00:00.000] ERROR: error {\n \"code\": 400,\n \"error\": \"uncapped jar\"\n}\n"), + want: []byte("[00:00:00.000] INFO: info {\n \"foo\": \"bar\",\n \"user\": \"alice\"\n}\n[00:00:00.000] WARN: warning {\n \"code\": 404,\n \"error\": \"not found\"\n}\n[00:00:00.000] ERROR: error {\n \"code\": 400,\n \"error\": \"uncapped jar\"\n}\n"), }, { name: "Trace", opts: &console.Options{HandlerOptions: &slog.HandlerOptions{Level: rlog.LevelTrace}}, - want: []byte("\x1b[37m[18:00:00.000]\x1b[0m \x1b[37mDEBUG-4:\x1b[0m \x1b[97mtracing\x1b[0m {\"foo\":\"bar\"}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[36mDEBUG:\x1b[0m \x1b[97mdebugging\x1b[0m {\"foo\":\"bar\",\"user\":\"bob\"}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\"foo\":\"bar\",\"user\":\"alice\"}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\"code\":404,\"error\":\"not found\"}\n\x1b[37m[18:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\"code\":400,\"error\":\"uncapped jar\"}\n"), + want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[37mDEBUG-4:\x1b[0m \x1b[97mtracing\x1b[0m {\"foo\":\"bar\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[36mDEBUG:\x1b[0m \x1b[97mdebugging\x1b[0m {\"foo\":\"bar\",\"user\":\"bob\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\"foo\":\"bar\",\"user\":\"alice\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\"code\":404,\"error\":\"not found\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\"code\":400,\"error\":\"uncapped jar\"}\n"), }, } @@ -115,7 +120,12 @@ func TestHandler_WithAttrs(t *testing.T) { t.Run(tc.name, func(t *testing.T) { synctest.Test(t, func(t *testing.T) { var buf bytes.Buffer - logger := rlog.New(slog.New(console.New(&buf, tc.opts))) + opts := tc.opts + if opts == nil { + opts = &console.Options{} + } + opts.UTCTime = true + logger := rlog.New(slog.New(console.New(&buf, opts))) ctx := context.Background() logger.TraceAttrs(ctx, "tracing", slog.String("foo", "bar")) @@ -124,8 +134,10 @@ func TestHandler_WithAttrs(t *testing.T) { logger.WarnAttrs(ctx, "warning", slog.String("error", "not found"), slog.Int("code", 404)) logger.ErrorAttrs(ctx, "error", slog.String("error", "uncapped jar"), slog.Int("code", 400)) - assert.True(t, bytes.Equal(buf.Bytes(), tc.want)) + assert.True(t, bytes.Equal(buf.Bytes(), tc.want), "got:\n%q \nwant:\n%q", buf.Bytes(), tc.want) }) }) } } + +// TODO: write a test helper to turn the console logs from a console.Handler into a map[string]any for using slogtest.TestHandler diff --git a/rlog/console/options.go b/rlog/console/options.go index 12d7074..8abd880 100644 --- a/rlog/console/options.go +++ b/rlog/console/options.go @@ -16,4 +16,7 @@ type Options struct { // Marking true causes the handler to format the logs without JSON dictionary of attributes. NoJSON bool + + // Marking true causes the handler to format the time using the UTC timezone. + UTCTime bool } From 4f4e4dcbc9be355a049747463e96507294d1575e Mon Sep 17 00:00:00 2001 From: Chris Okuda Date: Sat, 28 Mar 2026 12:40:03 -1000 Subject: [PATCH 05/18] update to add go 1.26 --- .github/workflows/test.yaml | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/.github/workflows/test.yaml b/.github/workflows/test.yaml index f195282..a86c72b 100644 --- a/.github/workflows/test.yaml +++ b/.github/workflows/test.yaml @@ -22,7 +22,7 @@ jobs: - name: Set up Go uses: actions/setup-go@v5 with: - go-version: 1.25.x + go-version: 1.26.x - name: Checkout Code uses: actions/checkout@v4 @@ -41,7 +41,7 @@ jobs: strategy: fail-fast: true matrix: - go-version: [1.24.x, 1.25.x] + go-version: [1.24.x, 1.25.x, 1.26.x] env: GOPATH: ${{ github.workspace }}/go GOBIN: ${{ github.workspace }}/go/bin From d3d56bddc9794db45bfcb1a08f5320241431d704 Mon Sep 17 00:00:00 2001 From: Chris Okuda Date: Sat, 28 Mar 2026 13:23:26 -1000 Subject: [PATCH 06/18] move the fanout handler to its own package, move the doc comment, and rename the logger file to rlog --- rlog/doc.go | 68 --------------------------- rlog/{ => fanout}/fanout.go | 34 +++++++------- rlog/{ => fanout}/fanout_test.go | 13 ++--- rlog/{logger.go => rlog.go} | 67 ++++++++++++++++++++++++++ rlog/{logger_test.go => rlog_test.go} | 0 5 files changed, 91 insertions(+), 91 deletions(-) delete mode 100644 rlog/doc.go rename rlog/{ => fanout}/fanout.go (54%) rename rlog/{ => fanout}/fanout_test.go (93%) rename rlog/{logger.go => rlog.go} (82%) rename rlog/{logger_test.go => rlog_test.go} (100%) diff --git a/rlog/doc.go b/rlog/doc.go deleted file mode 100644 index 8b6c0c8..0000000 --- a/rlog/doc.go +++ /dev/null @@ -1,68 +0,0 @@ -// Package rlog wraps [log/slog] with extra levels (Trace, Fatal, Panic), test -// capture helpers, and small slog utilities (handler options, global level sync, -// multi-sink fan-out). See [README.md in the repo], or [rlog on pkg.go.dev], for -// API summary and usage notes. -// -// package main -// -// import ( -// "context" -// "log/slog" -// "os" -// -// "go.rtnl.ai/x/rlog" -// ) -// -// func main() { -// // Global default logger (JSON stdout): allow Trace. -// rlog.SetLevel(rlog.LevelTrace) -// rlog.Info("hello") -// // Output example: {"time":"2026-03-25T12:00:00.000-00:00","level":"INFO","msg":"hello"} -// rlog.Trace("verbose") -// // Output example: {"time":"…","level":"TRACE","msg":"verbose"} -// -// // Custom logger: MergeWithCustomLevels names TRACE/FATAL/PANIC; WithGlobalLevel ties -// // level to rlog.SetLevel so this handler follows the same threshold as the default. -// opts := rlog.MergeWithCustomLevels(rlog.WithGlobalLevel(nil)) -// log := rlog.New(slog.New(slog.NewJSONHandler(os.Stdout, opts))) -// -// // rlog-only level + key/value fields (Trace also has TraceContext, TraceAttrs, …). -// log.Trace("trace-msg", "k", "v") -// // Output example: {"time":"…","level":"TRACE","msg":"trace-msg","k":"v"} -// -// // Without a hook, Fatal would os.Exit(1) and the rest of main would not run. -// rlog.SetFatalHook(func() {}) // demo only — replace with test hook or omit in production -// defer rlog.SetFatalHook(nil) // setting the fatal hook to nil causes future Fatal calls to use os.Exit(1) -// log.Fatal("fatal-msg") -// // Output example: {"time":"…","level":"FATAL","msg":"fatal-msg"} — then runs the fatal hook (no exit here) -// -// // Panic levels call panic("panic-msg") after logging -// func() { -// defer func() { recover() }() -// log.Panic("panic-msg") -// // Output example: {"time":"…","level":"PANIC","msg":"panic-msg"} — then panic("panic-msg") -// }() -// -// // WithGroup/With return *rlog.Logger and work the same as for a slog.Logger. -// sub := log.WithGroup("svc").With("name", "api") -// sub.Info("scoped") -// // Output example: {"time":"…","level":"INFO","msg":"scoped","svc":{"name":"api"}} -// -// // Stdlib-style context and slog.Attr APIs on *rlog.Logger. -// log.DebugContext(context.Background(), "debug-msg", "k", "v") -// // Output example: {"time":"…","level":"DEBUG","msg":"debug-msg","k":"v"} -// log.InfoAttrs(context.Background(), "info-msg", slog.String("k", "v")) -// // Output example: {"time":"…","level":"INFO","msg":"info-msg","k":"v"} -// -// // Package-level helpers and slog.Default now use this logger. -// new := log.With(slog.String("new", "logger")) -// rlog.SetDefault(new) -// rlog.Warn("via package after SetDefault") -// // Output example: {"time":"…","level":"WARN","msg":"via package after SetDefault","new":"logger"} -// rlog.FatalAttrs("fatal-msg", slog.String("fatal", "attr")) -// // Output example: {"time":"…","level":"FATAL","msg":"fatal-msg","new":"logger","fatal":"attr"} — then runs the fatal hook (no exit here) -// } -// -// [README.md in the repo]: https://github.com/rotationalio/x/blob/main/rlog/README.md -// [rlog on pkg.go.dev]: https://pkg.go.dev/go.rtnl.ai/x/rlog -package rlog diff --git a/rlog/fanout.go b/rlog/fanout/fanout.go similarity index 54% rename from rlog/fanout.go rename to rlog/fanout/fanout.go index 9c5ec4c..84124a3 100644 --- a/rlog/fanout.go +++ b/rlog/fanout/fanout.go @@ -1,4 +1,4 @@ -package rlog +package fanout import ( "context" @@ -6,24 +6,24 @@ import ( "log/slog" ) -// FanOut is a [slog.Handler] that forwards each record to every child handler, -// using a fresh [slog.Record.Clone] per child. For Go 1.26 or later, use the -// standard library's [slog.MultiHandler] instead; this is a clone of the -// functionality for Go 1.25 and earlier. -type FanOut struct { +// The fanout handler is a [slog.Handler] that forwards each record to every +// child handler, using a fresh [slog.Record.Clone] per child. For Go 1.26 or +// later, use the standard library's [slog.MultiHandler] instead; this is a clone +// of the functionality for Go 1.25 and earlier. +type Handler struct { handlers []slog.Handler } -// NewFanOut returns a new [FanOut] that forwards each record to every child +// New returns a new fanout [Handler] that forwards each record to every child // handler. For Go 1.26 or later, use [slog.MultiHandler] instead; this is a // clone of the functionality for Go 1.25 and earlier. -func NewFanOut(handlers ...slog.Handler) *FanOut { +func New(handlers ...slog.Handler) *Handler { hs := append([]slog.Handler(nil), handlers...) - return &FanOut{handlers: hs} + return &Handler{handlers: hs} } // Enabled reports whether any child handler accepts the given level. -func (f *FanOut) Enabled(ctx context.Context, level slog.Level) bool { +func (f *Handler) Enabled(ctx context.Context, level slog.Level) bool { for _, h := range f.handlers { if h.Enabled(ctx, level) { return true @@ -34,7 +34,7 @@ func (f *FanOut) Enabled(ctx context.Context, level slog.Level) bool { // Handle forwards a clone of r to each child that [slog.Handler.Enabled] accepts // for r's level, and joins any non-nil errors. -func (f *FanOut) Handle(ctx context.Context, r slog.Record) error { +func (f *Handler) Handle(ctx context.Context, r slog.Record) error { if len(f.handlers) == 0 { return nil } @@ -53,8 +53,8 @@ func (f *FanOut) Handle(ctx context.Context, r slog.Record) error { return errors.Join(errs...) } -// WithAttrs returns a [FanOut] whose children are wrapped with the same attrs. -func (f *FanOut) WithAttrs(attrs []slog.Attr) slog.Handler { +// WithAttrs returns a [Handler] whose children are wrapped with the same attrs. +func (f *Handler) WithAttrs(attrs []slog.Attr) slog.Handler { if len(attrs) == 0 { return f } @@ -65,11 +65,11 @@ func (f *FanOut) WithAttrs(attrs []slog.Attr) slog.Handler { next[i] = h.WithAttrs(attrs) } - return &FanOut{handlers: next} + return &Handler{handlers: next} } -// WithGroup returns a [FanOut] whose children are wrapped with the same group. -func (f *FanOut) WithGroup(name string) slog.Handler { +// WithGroup returns a [Handler] whose children are wrapped with the same group. +func (f *Handler) WithGroup(name string) slog.Handler { if name == "" { return f } @@ -80,5 +80,5 @@ func (f *FanOut) WithGroup(name string) slog.Handler { next[i] = h.WithGroup(name) } - return &FanOut{handlers: next} + return &Handler{handlers: next} } diff --git a/rlog/fanout_test.go b/rlog/fanout/fanout_test.go similarity index 93% rename from rlog/fanout_test.go rename to rlog/fanout/fanout_test.go index 2cca750..a4aae97 100644 --- a/rlog/fanout_test.go +++ b/rlog/fanout/fanout_test.go @@ -1,4 +1,4 @@ -package rlog_test +package fanout_test import ( "bytes" @@ -11,6 +11,7 @@ import ( "go.rtnl.ai/x/assert" "go.rtnl.ai/x/rlog" + "go.rtnl.ai/x/rlog/fanout" rlogtesting "go.rtnl.ai/x/rlog/testing" ) @@ -19,7 +20,7 @@ func TestFanOut_Handle_clonesToEachSink(t *testing.T) { var a, b bytes.Buffer ha := slog.NewJSONHandler(&a, rlog.MergeWithCustomLevels(&slog.HandlerOptions{Level: slog.LevelInfo})) hb := slog.NewJSONHandler(&b, rlog.MergeWithCustomLevels(&slog.HandlerOptions{Level: slog.LevelInfo})) - f := rlog.NewFanOut(ha, hb) + f := fanout.New(ha, hb) ctx := context.Background() r := slog.NewRecord(time.Now(), slog.LevelInfo, "hello", 0) @@ -34,7 +35,7 @@ func TestFanOut_Enabled_OR(t *testing.T) { var quiet, loud bytes.Buffer hQuiet := slog.NewJSONHandler(&quiet, &slog.HandlerOptions{Level: slog.LevelError}) hLoud := slog.NewJSONHandler(&loud, &slog.HandlerOptions{Level: slog.LevelDebug}) - f := rlog.NewFanOut(hQuiet, hLoud) + f := fanout.New(hQuiet, hLoud) ctx := context.Background() assert.True(t, f.Enabled(ctx, slog.LevelInfo), "loud child accepts Info") @@ -46,7 +47,7 @@ func TestFanOut_Handle_skipsDisabledChildren(t *testing.T) { var quiet, loud bytes.Buffer hQuiet := slog.NewJSONHandler(&quiet, &slog.HandlerOptions{Level: slog.LevelError}) hLoud := slog.NewJSONHandler(&loud, &slog.HandlerOptions{Level: slog.LevelDebug}) - f := rlog.NewFanOut(hQuiet, hLoud) + f := fanout.New(hQuiet, hLoud) ctx := context.Background() r := slog.NewRecord(time.Now(), slog.LevelInfo, "hello", 0) @@ -61,7 +62,7 @@ func TestFanOut_WithGroup_propagates(t *testing.T) { var a, b bytes.Buffer ha := slog.NewJSONHandler(&a, rlog.MergeWithCustomLevels(&slog.HandlerOptions{Level: slog.LevelInfo})) hb := slog.NewJSONHandler(&b, rlog.MergeWithCustomLevels(&slog.HandlerOptions{Level: slog.LevelInfo})) - f := rlog.NewFanOut(ha, hb).WithGroup("outer").(*rlog.FanOut) + f := fanout.New(ha, hb).WithGroup("outer").(*fanout.Handler) ctx := context.Background() r := slog.NewRecord(time.Now(), slog.LevelInfo, "msg", 0) @@ -78,7 +79,7 @@ func TestFanOut_WithGroup_propagates(t *testing.T) { func TestFanOut_slogtest_singleChild(t *testing.T) { var buf bytes.Buffer h := slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelInfo}) - fan := rlog.NewFanOut(h) + fan := fanout.New(h) err := slogtest.TestHandler(fan, func() []map[string]any { var maps []map[string]any diff --git a/rlog/logger.go b/rlog/rlog.go similarity index 82% rename from rlog/logger.go rename to rlog/rlog.go index 28f2a85..865529a 100644 --- a/rlog/logger.go +++ b/rlog/rlog.go @@ -1,3 +1,70 @@ +// Package rlog wraps [log/slog] with extra levels (Trace, Fatal, Panic), test +// capture helpers, and small slog utilities (handler options, global level sync, +// multi-sink fan-out). See [README.md in the repo], or [rlog on pkg.go.dev], for +// API summary and usage notes. +// +// package main +// +// import ( +// "context" +// "log/slog" +// "os" +// +// "go.rtnl.ai/x/rlog" +// ) +// +// func main() { +// // Global default logger (JSON stdout): allow Trace. +// rlog.SetLevel(rlog.LevelTrace) +// rlog.Info("hello") +// // Output example: {"time":"2026-03-25T12:00:00.000-00:00","level":"INFO","msg":"hello"} +// rlog.Trace("verbose") +// // Output example: {"time":"…","level":"TRACE","msg":"verbose"} +// +// // Custom logger: MergeWithCustomLevels names TRACE/FATAL/PANIC; WithGlobalLevel ties +// // level to rlog.SetLevel so this handler follows the same threshold as the default. +// opts := rlog.MergeWithCustomLevels(rlog.WithGlobalLevel(nil)) +// log := rlog.New(slog.New(slog.NewJSONHandler(os.Stdout, opts))) +// +// // rlog-only level + key/value fields (Trace also has TraceContext, TraceAttrs, …). +// log.Trace("trace-msg", "k", "v") +// // Output example: {"time":"…","level":"TRACE","msg":"trace-msg","k":"v"} +// +// // Without a hook, Fatal would os.Exit(1) and the rest of main would not run. +// rlog.SetFatalHook(func() {}) // demo only — replace with test hook or omit in production +// defer rlog.SetFatalHook(nil) // setting the fatal hook to nil causes future Fatal calls to use os.Exit(1) +// log.Fatal("fatal-msg") +// // Output example: {"time":"…","level":"FATAL","msg":"fatal-msg"} — then runs the fatal hook (no exit here) +// +// // Panic levels call panic("panic-msg") after logging +// func() { +// defer func() { recover() }() +// log.Panic("panic-msg") +// // Output example: {"time":"…","level":"PANIC","msg":"panic-msg"} — then panic("panic-msg") +// }() +// +// // WithGroup/With return *rlog.Logger and work the same as for a slog.Logger. +// sub := log.WithGroup("svc").With("name", "api") +// sub.Info("scoped") +// // Output example: {"time":"…","level":"INFO","msg":"scoped","svc":{"name":"api"}} +// +// // Stdlib-style context and slog.Attr APIs on *rlog.Logger. +// log.DebugContext(context.Background(), "debug-msg", "k", "v") +// // Output example: {"time":"…","level":"DEBUG","msg":"debug-msg","k":"v"} +// log.InfoAttrs(context.Background(), "info-msg", slog.String("k", "v")) +// // Output example: {"time":"…","level":"INFO","msg":"info-msg","k":"v"} +// +// // Package-level helpers and slog.Default now use this logger. +// new := log.With(slog.String("new", "logger")) +// rlog.SetDefault(new) +// rlog.Warn("via package after SetDefault") +// // Output example: {"time":"…","level":"WARN","msg":"via package after SetDefault","new":"logger"} +// rlog.FatalAttrs("fatal-msg", slog.String("fatal", "attr")) +// // Output example: {"time":"…","level":"FATAL","msg":"fatal-msg","new":"logger","fatal":"attr"} — then runs the fatal hook (no exit here) +// } +// +// [README.md in the repo]: https://github.com/rotationalio/x/blob/main/rlog/README.md +// [rlog on pkg.go.dev]: https://pkg.go.dev/go.rtnl.ai/x/rlog package rlog import ( diff --git a/rlog/logger_test.go b/rlog/rlog_test.go similarity index 100% rename from rlog/logger_test.go rename to rlog/rlog_test.go From 7329bf02c87f50ce8315c3f5a2cb86a18429061a Mon Sep 17 00:00:00 2001 From: Chris Okuda Date: Sat, 28 Mar 2026 14:29:26 -1000 Subject: [PATCH 07/18] Rewrote the handler to pass the slogtest.TestHandler test and added more tests to verify other features. Also implemented the AddSource and ReplaceAttr features. --- rlog/console/color.go | 2 + rlog/console/console.go | 348 ++++++++++++++++++++++++----------- rlog/console/console_test.go | 207 +++++++++++++-------- rlog/console/parse.go | 122 ++++++++++++ 4 files changed, 499 insertions(+), 180 deletions(-) create mode 100644 rlog/console/parse.go diff --git a/rlog/console/color.go b/rlog/console/color.go index baf546f..cfbebaf 100644 --- a/rlog/console/color.go +++ b/rlog/console/color.go @@ -5,6 +5,7 @@ import ( "io" ) +// SGR foreground codes for the handler prefix (see colorize). const ( red = 31 cyan = 36 @@ -15,6 +16,7 @@ const ( white = 97 ) +// colorize wraps text in ANSI foreground + reset. func colorize(w io.Writer, color uint8, text string) { fmt.Fprintf(w, "\033[%dm%s\033[0m", color, text) } diff --git a/rlog/console/console.go b/rlog/console/console.go index 93772ae..6378c87 100644 --- a/rlog/console/console.go +++ b/rlog/console/console.go @@ -1,7 +1,5 @@ -// Package console provides a console handler for the rlog package that pretty prints -// colored text logs to stdout. It is a wrapper around the slog.Handler interface. -// -// NOTE: this should only be used for testing and development. +// Package console implements a [slog.Handler] that pretty-prints log lines with optional colors +// and a trailing JSON object of attributes. For development and tests, not high-throughput logging. package console import ( @@ -11,189 +9,325 @@ import ( "fmt" "io" "log/slog" + "path/filepath" + "slices" "sync" "go.rtnl.ai/x/rlog" ) -const ( - timeFormat = "[15:04:05.000]" -) +const timeFormat = "[15:04:05.000]" +// Handler writes a text prefix (source, time, level, message) and optional JSON attributes. type Handler struct { - slog.Handler - w io.Writer - mu *sync.Mutex - opts Options + w io.Writer + mu *sync.Mutex + opts Options + topAttrs []slog.Attr + segments []segment +} + +// segment is one [slog.Handler.WithGroup] name plus attributes. +type segment struct { + name string + attrs []slog.Attr } +// New creates a [Handler] writing to w. If opts is nil, all defaults are used. func New(w io.Writer, opts *Options) *Handler { if opts == nil { opts = &Options{} } return &Handler{ - Handler: slog.NewTextHandler(w, opts.HandlerOptions), - w: w, - opts: *opts, - mu: &sync.Mutex{}, + w: w, + opts: *opts, + mu: &sync.Mutex{}, } } +// Ensure that Handler implements the slog.Handler interface. var _ slog.Handler = (*Handler)(nil) +// Enabled reports whether the handler is enabled for the given level. +func (h *Handler) Enabled(_ context.Context, level slog.Level) bool { + if h.opts.HandlerOptions == nil || h.opts.Level == nil { + return level >= slog.LevelInfo + } + return level >= h.opts.Level.Level() +} + +// WithAttrs returns a new handler with the given attributes. func (h *Handler) WithAttrs(attrs []slog.Attr) slog.Handler { - return &Handler{ - Handler: h.Handler.WithAttrs(attrs), - w: h.w, - mu: h.mu, // mutex shared by all clones of this handler - opts: h.opts, + if len(attrs) == 0 { + return h + } + if len(h.segments) == 0 { + top := h.topAttrs + if len(top) > 0 { + top = append(slices.Clone(top), attrs...) + } else { + top = attrs + } + return &Handler{w: h.w, mu: h.mu, opts: h.opts, topAttrs: top, segments: h.segments} } + segs := slices.Clone(h.segments) + last := len(segs) - 1 + if len(segs[last].attrs) > 0 { + segs[last].attrs = append(slices.Clone(segs[last].attrs), attrs...) + } else { + segs[last].attrs = attrs + } + return &Handler{w: h.w, mu: h.mu, opts: h.opts, topAttrs: h.topAttrs, segments: segs} } +// WithGroup returns a new handler with the given group. func (h *Handler) WithGroup(name string) slog.Handler { - return &Handler{ - Handler: h.Handler.WithGroup(name), - w: h.w, - mu: h.mu, // mutex shared by all clones of this handler - opts: h.opts, + if name == "" { + return h } + segs := append(slices.Clone(h.segments), segment{name: name}) + return &Handler{w: h.w, mu: h.mu, opts: h.opts, topAttrs: h.topAttrs, segments: segs} } -func (h *Handler) Handle(ctx context.Context, r slog.Record) error { - // Write to a buffer first to avoid race conditions with the writer. - // NOTE: slog uses an internal pool-allocated bytes buffer for performance. - // Because we're allocating a new buffer here, this handler should not be used in - // performance intensive applications. +// Handle writes the record to the handler's writer. +func (h *Handler) Handle(_ context.Context, r slog.Record) error { var buf bytes.Buffer - // Print the timestamp. + // Optional ReplaceAttr hook (nil group path for built-ins). + var repl func([]string, slog.Attr) slog.Attr + if h.opts.HandlerOptions != nil { + repl = h.opts.ReplaceAttr + } + + // Time tm := r.Time if h.opts.UTCTime { tm = tm.UTC() } - if h.opts.NoColor { - fmt.Fprint(&buf, tm.Format(timeFormat)) - } else { - colorize(&buf, lightGray, tm.Format(timeFormat)) + var timeAttr slog.Attr + if !tm.IsZero() { + timeAttr = slog.Time(slog.TimeKey, tm) + if repl != nil { + timeAttr = repl(nil, timeAttr) + } } - // Space separator between timestamp and level. - buf.WriteRune(' ') + // Level + levelAttr := slog.Any(slog.LevelKey, r.Level) + if repl != nil { + levelAttr = repl(nil, levelAttr) + } - // Print the level. - level := r.Level.String() + ":" - if h.opts.NoColor { + // Message + msgAttr := slog.String(slog.MessageKey, r.Message) + if repl != nil { + msgAttr = repl(nil, msgAttr) + } + + // Source (optional) + showSource := false + var srcAttr slog.Attr + if h.opts.HandlerOptions != nil && h.opts.AddSource && r.PC != 0 { + if src := r.Source(); src != nil { + srcAttr = slog.Any(slog.SourceKey, src) + if repl != nil { + srcAttr = repl(nil, srcAttr) + } + showSource = !srcAttr.Equal(slog.Attr{}) + } + } + if showSource { + writeSourcePrefix(&buf, h.opts.NoColor, srcAttr) + } + + if !timeAttr.Equal(slog.Attr{}) && timeAttr.Value.Kind() == slog.KindTime && !timeAttr.Value.Time().IsZero() { + tm2 := timeAttr.Value.Time() + if h.opts.UTCTime { + tm2 = tm2.UTC() + } + writePlainOrColor(&buf, h.opts.NoColor, lightGray, tm2.Format(timeFormat)) + buf.WriteRune(' ') + } + + lv := levelForOutput(levelAttr, r.Level) + level := lv.String() + ":" + if code, ok := levelANSICode(lv); h.opts.NoColor || !ok { fmt.Fprint(&buf, level) } else { - switch r.Level { - case rlog.LevelTrace: - colorize(&buf, lightGray, level) - case slog.LevelDebug: - colorize(&buf, cyan, level) - case slog.LevelInfo: - colorize(&buf, lightGreen, level) - case slog.LevelWarn: - colorize(&buf, lightYellow, level) - case slog.LevelError: - colorize(&buf, lightRed, level) - case rlog.LevelFatal: - colorize(&buf, red, level) - case rlog.LevelPanic: - colorize(&buf, red, level) - default: - fmt.Fprint(&buf, level) - } - } - - // Space separator between level and message. + colorize(&buf, code, level) + } + buf.WriteRune(' ') - // Print the message. - if h.opts.NoColor { - fmt.Fprint(&buf, r.Message) - } else { - colorize(&buf, white, r.Message) + msg := r.Message + if !msgAttr.Equal(slog.Attr{}) && msgAttr.Value.Kind() == slog.KindString { + msg = msgAttr.Value.String() } + writePlainOrColor(&buf, h.opts.NoColor, white, msg) + // User attrs: collect record fields (skip duplicates of built-ins), merge With/WithGroup stack. + var recAttrs []slog.Attr + r.Attrs(func(a slog.Attr) bool { + if a.Key == slog.LevelKey || a.Key == slog.MessageKey || a.Key == slog.TimeKey { + return true + } + recAttrs = append(recAttrs, a) + return true + }) + merged := buildMergedUserAttrs(h.topAttrs, h.segments, recAttrs) + + // Trailing JSON object (compact or indented), or newline only when NoJSON. if !h.opts.NoJSON { - // Space separator between message and JSON dictionary. buf.WriteRune(' ') - - // Gather the attributes. attrs := make(map[string]any) - r.Attrs(func(a slog.Attr) bool { - // Skip the level, message, and time keys. - if a.Key == slog.LevelKey || a.Key == slog.MessageKey || a.Key == slog.TimeKey { - return true - } - addAttr(attrs, a) - return true - }) - - // Print the JSON dictionary of attributes. - encoder := json.NewEncoder(&buf) + for _, a := range merged { + mergeAttrJSON(attrs, nil, a, repl) + } + enc := json.NewEncoder(&buf) if h.opts.IndentJSON { - encoder.SetIndent("", " ") + enc.SetIndent("", " ") } - if err := encoder.Encode(attrs); err != nil { + if err := enc.Encode(attrs); err != nil { return err } } else { buf.WriteRune('\n') } - // Lock this mutex including all handler clones so that we can write to the writer safely. + // One write per record, serialized with sibling handlers sharing this mutex. h.mu.Lock() defer h.mu.Unlock() - if _, err := h.w.Write(buf.Bytes()); err != nil { - return err + _, err := h.w.Write(buf.Bytes()) + return err +} + +// writePlainOrColor prints text with or without ANSI color. +func writePlainOrColor(buf *bytes.Buffer, noColor bool, color uint8, text string) { + if noColor { + fmt.Fprint(buf, text) + } else { + colorize(buf, color, text) } - return nil } -// addAttr adds an attribute to the map, capturing groups properly. -func addAttr(attrs map[string]any, a slog.Attr) { - // Resolve the value of the attribute. +// writeSourcePrefix prints basename:line when srcAttr carries *slog.Source. +func writeSourcePrefix(buf *bytes.Buffer, noColor bool, srcAttr slog.Attr) { + if srcAttr.Value.Kind() != slog.KindAny { + return + } + s, ok := srcAttr.Value.Any().(*slog.Source) + if !ok || s == nil || (s.File == "" && s.Line == 0) { + return + } + writePlainOrColor(buf, noColor, lightGray, fmt.Sprintf("%s:%d ", filepath.Base(s.File), s.Line)) +} + +// levelForOutput prefers a slog.Level inside levelAttr after ReplaceAttr. +func levelForOutput(levelAttr slog.Attr, fallback slog.Level) slog.Level { + if levelAttr.Equal(slog.Attr{}) { + return fallback + } + if levelAttr.Value.Kind() == slog.KindAny { + if l, ok := levelAttr.Value.Any().(slog.Level); ok { + return l + } + } + return fallback +} + +// levelANSICode maps standard and rlog levels to a color; ok false means uncolored. +func levelANSICode(lv slog.Level) (code uint8, ok bool) { + switch lv { + case rlog.LevelTrace: + return lightGray, true + case slog.LevelDebug: + return cyan, true + case slog.LevelInfo: + return lightGreen, true + case slog.LevelWarn: + return lightYellow, true + case slog.LevelError: + return lightRed, true + case rlog.LevelFatal: + return red, true + case rlog.LevelPanic: + return red, true + default: + return 0, false + } +} + +// buildMergedUserAttrs wraps record attrs in innermost→outermost groups, then appends top attrs. +func buildMergedUserAttrs(top []slog.Attr, segs []segment, record []slog.Attr) []slog.Attr { + inner := slices.Clone(record) + for i := len(segs) - 1; i >= 0; i-- { + s := segs[i] + args := make([]any, 0, len(s.attrs)+len(inner)) + for _, a := range s.attrs { + args = append(args, a) + } + for _, a := range inner { + args = append(args, a) + } + inner = []slog.Attr{slog.Group(s.name, args...)} + } + return append(slices.Clone(top), inner...) +} + +// mergeAttrJSON flattens attrs into a JSON-ready map; ReplaceAttr gets the group path for leaves. +func mergeAttrJSON(attrs map[string]any, groups []string, a slog.Attr, repl func([]string, slog.Attr) slog.Attr) { a.Value = a.Value.Resolve() if a.Equal(slog.Attr{}) { return } - - // Add the attribute to the map. switch a.Value.Kind() { + // Recurse into group members; extend groups for named groups. case slog.KindGroup: - // Group values carry nested attrs (e.g. slog.Group("db", ...)). gattrs := a.Value.Group() if len(gattrs) == 0 { return } if a.Key != "" { - // Named group: nest under this key as a JSON object, merging with any - // prior attrs already stored for the same key. - var sub map[string]any - if existing, ok := attrs[a.Key].(map[string]any); ok { - sub = existing - } else { - sub = make(map[string]any) - attrs[a.Key] = sub - } - + g := append(slices.Clone(groups), a.Key) + sub := ensureSubmap(attrs, a.Key) for _, ga := range gattrs { - addAttr(sub, ga) + mergeAttrJSON(sub, g, ga, repl) } } else { - // Anonymous / inline group: add members at the current map level (no extra nesting). for _, ga := range gattrs { - addAttr(attrs, ga) + mergeAttrJSON(attrs, groups, ga, repl) } } default: - attrs[a.Key] = slogValueToJSON(a.Value) + // Leaf: ReplaceAttr, then store or re-enter if ReplaceAttr produced a group. + leaf := a + if repl != nil { + leaf = repl(groups, a) + } + if leaf.Equal(slog.Attr{}) { + return + } + leaf.Value = leaf.Value.Resolve() + if leaf.Value.Kind() == slog.KindGroup { + mergeAttrJSON(attrs, groups, leaf, nil) + return + } + attrs[leaf.Key] = slogValueToJSON(leaf.Value) + } +} + +// ensureSubmap returns attrs[key] as a nested map, creating it if needed. +func ensureSubmap(attrs map[string]any, key string) map[string]any { + if existing, ok := attrs[key].(map[string]any); ok { + return existing } + sub := make(map[string]any) + attrs[key] = sub + return sub } -// slogValueToJSON returns a value suitable for encoding/json from a resolved slog.Value. +// slogValueToJSON converts a resolved [slog.Value] for encoding/json. func slogValueToJSON(v slog.Value) any { switch v.Kind() { case slog.KindString: diff --git a/rlog/console/console_test.go b/rlog/console/console_test.go index 77663e1..dbc6fa1 100644 --- a/rlog/console/console_test.go +++ b/rlog/console/console_test.go @@ -4,15 +4,24 @@ import ( "bytes" "context" "log/slog" + "runtime" + "strings" "testing" + "testing/slogtest" "testing/synctest" + "time" "go.rtnl.ai/x/assert" "go.rtnl.ai/x/rlog" "go.rtnl.ai/x/rlog/console" ) -func TestHandler(t *testing.T) { +// TestHandler_GoldenTest tests the [Handler] with various options and verifies +// the output matches the golden bytes. NOTE: [slog.HandlerOptions.AddSource] is +// not tested here because it is hard to verify the output matches the golden bytes; +// we have a separate test for [slog.HandlerOptions.AddSource] called +// [TestHandler_AddSource_prefix]. +func TestHandler_GoldenTest(t *testing.T) { testCases := []struct { name string opts *console.Options @@ -21,12 +30,12 @@ func TestHandler(t *testing.T) { { name: "Default", opts: nil, - want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {}\n"), + want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\"req\":{\"foo\":\"bar\",\"id\":\"1\",\"user\":\"alice\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\"req\":{\"code\":404,\"error\":\"not found\",\"id\":\"1\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\"req\":{\"code\":400,\"error\":\"uncapped jar\",\"id\":\"1\"},\"svc\":\"api\"}\n"), }, { name: "NoColor", opts: &console.Options{NoColor: true}, - want: []byte("[00:00:00.000] INFO: info {}\n[00:00:00.000] WARN: warning {}\n[00:00:00.000] ERROR: error {}\n"), + want: []byte("[00:00:00.000] INFO: info {\"req\":{\"foo\":\"bar\",\"id\":\"1\",\"user\":\"alice\"},\"svc\":\"api\"}\n[00:00:00.000] WARN: warning {\"req\":{\"code\":404,\"error\":\"not found\",\"id\":\"1\"},\"svc\":\"api\"}\n[00:00:00.000] ERROR: error {\"req\":{\"code\":400,\"error\":\"uncapped jar\",\"id\":\"1\"},\"svc\":\"api\"}\n"), }, { name: "NoJSON", @@ -41,12 +50,17 @@ func TestHandler(t *testing.T) { { name: "IndentJSON", opts: &console.Options{IndentJSON: true}, - want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {}\n"), + want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\n \"req\": {\n \"foo\": \"bar\",\n \"id\": \"1\",\n \"user\": \"alice\"\n },\n \"svc\": \"api\"\n}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\n \"req\": {\n \"code\": 404,\n \"error\": \"not found\",\n \"id\": \"1\"\n },\n \"svc\": \"api\"\n}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\n \"req\": {\n \"code\": 400,\n \"error\": \"uncapped jar\",\n \"id\": \"1\"\n },\n \"svc\": \"api\"\n}\n"), + }, + { + name: "IndentJSONNoColor", + opts: &console.Options{IndentJSON: true, NoColor: true}, + want: []byte("[00:00:00.000] INFO: info {\n \"req\": {\n \"foo\": \"bar\",\n \"id\": \"1\",\n \"user\": \"alice\"\n },\n \"svc\": \"api\"\n}\n[00:00:00.000] WARN: warning {\n \"req\": {\n \"code\": 404,\n \"error\": \"not found\",\n \"id\": \"1\"\n },\n \"svc\": \"api\"\n}\n[00:00:00.000] ERROR: error {\n \"req\": {\n \"code\": 400,\n \"error\": \"uncapped jar\",\n \"id\": \"1\"\n },\n \"svc\": \"api\"\n}\n"), }, { name: "Trace", opts: &console.Options{HandlerOptions: &slog.HandlerOptions{Level: rlog.LevelTrace}}, - want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[37mDEBUG-4:\x1b[0m \x1b[97mtracing\x1b[0m {}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[36mDEBUG:\x1b[0m \x1b[97mdebugging\x1b[0m {}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {}\n"), + want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[37mDEBUG-4:\x1b[0m \x1b[97mtracing\x1b[0m {\"req\":{\"foo\":\"bar\",\"id\":\"1\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[36mDEBUG:\x1b[0m \x1b[97mdebugging\x1b[0m {\"req\":{\"foo\":\"bar\",\"id\":\"1\",\"user\":\"bob\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\"req\":{\"foo\":\"bar\",\"id\":\"1\",\"user\":\"alice\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\"req\":{\"code\":404,\"error\":\"not found\",\"id\":\"1\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\"req\":{\"code\":400,\"error\":\"uncapped jar\",\"id\":\"1\"},\"svc\":\"api\"}\n"), }, } @@ -59,13 +73,15 @@ func TestHandler(t *testing.T) { opts = &console.Options{} } opts.UTCTime = true - logger := rlog.New(slog.New(console.New(&buf, opts))) + base := rlog.New(slog.New(console.New(&buf, opts))) + log := base.With(slog.String("svc", "api")).WithGroup("req").With(slog.String("id", "1")) + ctx := context.Background() - logger.Trace("tracing") - logger.Debug("debugging") - logger.Info("info") - logger.Warn("warning") - logger.Error("error") + log.TraceAttrs(ctx, "tracing", slog.String("foo", "bar")) + log.DebugAttrs(ctx, "debugging", slog.String("foo", "bar"), slog.String("user", "bob")) + log.InfoAttrs(ctx, "info", slog.String("foo", "bar"), slog.String("user", "alice")) + log.WarnAttrs(ctx, "warning", slog.String("error", "not found"), slog.Int("code", 404)) + log.ErrorAttrs(ctx, "error", slog.String("error", "uncapped jar"), slog.Int("code", 400)) assert.True(t, bytes.Equal(buf.Bytes(), tc.want), "got:\n%q \nwant:\n%q", buf.Bytes(), tc.want) }) @@ -73,71 +89,116 @@ func TestHandler(t *testing.T) { } } -func TestHandler_WithAttrs(t *testing.T) { - testCases := []struct { - name string - opts *console.Options - want []byte - }{ - { - name: "Default", - opts: nil, - want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\"foo\":\"bar\",\"user\":\"alice\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\"code\":404,\"error\":\"not found\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\"code\":400,\"error\":\"uncapped jar\"}\n"), - }, - { - name: "NoColor", - opts: &console.Options{NoColor: true}, - want: []byte("[00:00:00.000] INFO: info {\"foo\":\"bar\",\"user\":\"alice\"}\n[00:00:00.000] WARN: warning {\"code\":404,\"error\":\"not found\"}\n[00:00:00.000] ERROR: error {\"code\":400,\"error\":\"uncapped jar\"}\n"), - }, - { - name: "NoJSON", - opts: &console.Options{NoJSON: true}, - want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m\n"), - }, - { - name: "Plain", - opts: &console.Options{NoColor: true, NoJSON: true}, - want: []byte("[00:00:00.000] INFO: info\n[00:00:00.000] WARN: warning\n[00:00:00.000] ERROR: error\n"), - }, - { - name: "IndentJSON", - opts: &console.Options{IndentJSON: true}, - want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\n \"foo\": \"bar\",\n \"user\": \"alice\"\n}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\n \"code\": 404,\n \"error\": \"not found\"\n}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\n \"code\": 400,\n \"error\": \"uncapped jar\"\n}\n"), - }, - { - name: "IndentJSONNoColor", - opts: &console.Options{IndentJSON: true, NoColor: true}, - want: []byte("[00:00:00.000] INFO: info {\n \"foo\": \"bar\",\n \"user\": \"alice\"\n}\n[00:00:00.000] WARN: warning {\n \"code\": 404,\n \"error\": \"not found\"\n}\n[00:00:00.000] ERROR: error {\n \"code\": 400,\n \"error\": \"uncapped jar\"\n}\n"), - }, - { - name: "Trace", - opts: &console.Options{HandlerOptions: &slog.HandlerOptions{Level: rlog.LevelTrace}}, - want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[37mDEBUG-4:\x1b[0m \x1b[97mtracing\x1b[0m {\"foo\":\"bar\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[36mDEBUG:\x1b[0m \x1b[97mdebugging\x1b[0m {\"foo\":\"bar\",\"user\":\"bob\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\"foo\":\"bar\",\"user\":\"alice\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\"code\":404,\"error\":\"not found\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\"code\":400,\"error\":\"uncapped jar\"}\n"), - }, +// TestHandler_slogtest runs [testing/slogtest.TestHandler] against [console.Handler]; each emitted line +// is parsed with [console.ParseLogLine] to build the result maps. Options use plain text and compact JSON +// so one line equals one log record. +func TestHandler_slogtest(t *testing.T) { + var buf bytes.Buffer + opts := &console.Options{ + HandlerOptions: &slog.HandlerOptions{Level: slog.LevelInfo}, + NoColor: true, + UTCTime: true, } + h := console.New(&buf, opts) + err := slogtest.TestHandler(h, func() []map[string]any { + var maps []map[string]any + for _, line := range strings.Split(strings.TrimSpace(buf.String()), "\n") { + if line == "" { + continue + } + m, e := console.ParseLogLine(line) + if e != nil { + t.Fatalf("ParseLogLine(%q): %v", line, e) + } + maps = append(maps, m) + } + return maps + }) + assert.Ok(t, err, "handler should satisfy slogtest when each line is round-tripped through ParseLogLine") +} - for _, tc := range testCases { - t.Run(tc.name, func(t *testing.T) { - synctest.Test(t, func(t *testing.T) { - var buf bytes.Buffer - opts := tc.opts - if opts == nil { - opts = &console.Options{} - } - opts.UTCTime = true - logger := rlog.New(slog.New(console.New(&buf, opts))) - ctx := context.Background() +// TestHandler_WithGroup_mergedIntoJSON checks that logger.With("a","b").WithGroup("G") nests record attrs +// under G in the JSON tail and that [console.ParseLogLine] sees the same shape. +func TestHandler_WithGroup_mergedIntoJSON(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + var buf bytes.Buffer + opts := &console.Options{NoColor: true, UTCTime: true} + log := slog.New(console.New(&buf, opts)).With("a", "b").WithGroup("G") + log.Info("msg", "k", "v") - logger.TraceAttrs(ctx, "tracing", slog.String("foo", "bar")) - logger.DebugAttrs(ctx, "debugging", slog.String("foo", "bar"), slog.String("user", "bob")) - logger.InfoAttrs(ctx, "info", slog.String("foo", "bar"), slog.String("user", "alice")) - logger.WarnAttrs(ctx, "warning", slog.String("error", "not found"), slog.Int("code", 404)) - logger.ErrorAttrs(ctx, "error", slog.String("error", "uncapped jar"), slog.Int("code", 400)) + m, err := console.ParseLogLine(strings.TrimSpace(buf.String())) + assert.Ok(t, err, "single Info line with group should parse") + g, ok := m["G"].(map[string]any) + assert.True(t, ok, `top-level key "G" should be a nested map from WithGroup`) + assert.Equal(t, "v", g["k"], "record attr k should appear inside group G") + assert.Equal(t, "msg", m[slog.MessageKey], "msg should be the log message text") + }) +} - assert.True(t, bytes.Equal(buf.Bytes(), tc.want), "got:\n%q \nwant:\n%q", buf.Bytes(), tc.want) - }) - }) - } +// TestHandler_ReplaceAttr_dropsKey verifies [slog.HandlerOptions.ReplaceAttr] removes a user key from +// the JSON object while leaving other attrs (JSON numbers decode as float64 in the parsed map). +func TestHandler_ReplaceAttr_dropsKey(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + var buf bytes.Buffer + opts := &console.Options{ + NoColor: true, + UTCTime: true, + HandlerOptions: &slog.HandlerOptions{ + Level: slog.LevelInfo, + ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr { + if a.Key == "drop" { + return slog.Attr{} + } + return a + }, + }, + } + log := slog.New(console.New(&buf, opts)) + log.Info("x", "keep", 1, "drop", "gone") + + m, err := console.ParseLogLine(strings.TrimSpace(buf.String())) + assert.Ok(t, err, "line with ReplaceAttr should still parse") + _, hasDrop := m["drop"] + assert.False(t, hasDrop, "ReplaceAttr should strip key drop from output") + assert.Equal(t, float64(1), m["keep"], "keep should remain and match JSON-decoded int") + }) } -// TODO: write a test helper to turn the console logs from a console.Handler into a map[string]any for using slogtest.TestHandler +// TestHandler_AddSource_prefix ensures AddSource adds a basename:line prefix and ParseLogLine exposes +// [slog.SourceKey] with File and Line when Handle receives a record built with a non-zero PC. +func TestHandler_AddSource_prefix(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + var buf bytes.Buffer + opts := &console.Options{ + NoColor: true, + UTCTime: true, + HandlerOptions: &slog.HandlerOptions{ + Level: slog.LevelInfo, + AddSource: true, + }, + } + h := console.New(&buf, opts) + pc := callerPC(2) + r := slog.NewRecord(time.Now(), slog.LevelInfo, "hello", pc) + assert.Ok(t, h.Handle(context.Background(), r), "Handle with AddSource should not error") + + line := strings.TrimSpace(buf.String()) + assert.True(t, strings.Contains(line, ":"), "AddSource should print file:line before the rest of the line; got %q", line) + + m, err := console.ParseLogLine(line) + assert.Ok(t, err, "line with source prefix should parse") + src, ok := m[slog.SourceKey].(map[string]any) + assert.True(t, ok, "SourceKey should be a map[string]any like JSON source objects") + _, hasFile := src["File"] + assert.True(t, hasFile, "parsed source should include File") + _, hasLine := src["Line"] + assert.True(t, hasLine, "parsed source should include Line") + }) +} + +// callerPC returns the PC at the given skip depth; skip=2 yields the test frame so [slog.Record] carries a real line. +func callerPC(skip int) uintptr { + var pcs [1]uintptr + runtime.Callers(skip, pcs[:]) + return pcs[0] +} diff --git a/rlog/console/parse.go b/rlog/console/parse.go new file mode 100644 index 0000000..e90f71d --- /dev/null +++ b/rlog/console/parse.go @@ -0,0 +1,122 @@ +package console + +import ( + "encoding/json" + "fmt" + "log/slog" + "maps" + "regexp" + "strconv" + "strings" + "time" +) + +// Line layout: optional source, optional [HH:MM:SS.mmm], LEVEL: message [JSON]. +var ( + ansiRegexp = regexp.MustCompile(`\x1b\[[0-9;]*m`) + sourcePrefixRx = regexp.MustCompile(`^([^\s]+:\d+)\s+`) + timeBracketRx = regexp.MustCompile(`^\[(\d{2}:\d{2}:\d{2}\.\d{3})\]\s+`) + levelPrefixRx = regexp.MustCompile(`^([A-Za-z0-9+-]+):\s+`) +) + +// ParseLogLine parses a single line from [Handler] into a map, e.g. for [testing/slogtest.TestHandler]. +// Expects one line per record (no IndentJSON); strips ANSI escapes. +func ParseLogLine(line string) (map[string]any, error) { + s := strings.TrimSpace(stripAnsi(line)) + if s == "" { + return nil, fmt.Errorf("empty line") + } + + m := make(map[string]any) + + // Parse optional source:line. + if sm := sourcePrefixRx.FindStringSubmatch(s); sm != nil { + file, lineNum, ok := parseSourceToken(sm[1]) + if ok { + m[slog.SourceKey] = map[string]any{ + "File": file, + "Line": float64(lineNum), + } + } + s = strings.TrimSpace(s[len(sm[0]):]) + } + + // Parse optional time bracket. + if tm := timeBracketRx.FindStringSubmatch(s); tm != nil { + clock, err := time.ParseInLocation("15:04:05.000", tm[1], time.UTC) + if err != nil { + return nil, fmt.Errorf("time bracket: %w", err) + } + t := time.Date(2000, 1, 1, clock.Hour(), clock.Minute(), clock.Second(), clock.Nanosecond(), time.UTC) + m[slog.TimeKey] = t + s = strings.TrimSpace(s[len(tm[0]):]) + } + + // Parse level. + lm := levelPrefixRx.FindStringSubmatch(s) + if lm == nil { + return nil, fmt.Errorf("no level prefix in %q", s) + } + levelStr := lm[1] + m[slog.LevelKey] = levelStr + s = strings.TrimSpace(s[len(lm[0]):]) + + // Parse JSON tail. + jsonPart, jStart, ok := extractOuterJSONObject(s) + if ok { + // Parse message. + m[slog.MessageKey] = strings.TrimSpace(s[:jStart]) + + // Parse JSON. + var obj map[string]any + if err := json.Unmarshal([]byte(jsonPart), &obj); err != nil { + return nil, fmt.Errorf("json tail: %w", err) + } + maps.Copy(m, obj) + } else { + // Parse message. + m[slog.MessageKey] = strings.TrimSpace(s) + } + + return m, nil +} + +// stripAnsi removes SGR sequences from s. +func stripAnsi(s string) string { + return ansiRegexp.ReplaceAllString(s, "") +} + +// extractOuterJSONObject finds the last top-level {...} in s (handles nested braces). +func extractOuterJSONObject(s string) (json string, start int, ok bool) { + end := strings.LastIndex(s, "}") + if end < 0 { + return "", 0, false + } + depth := 0 + for i := end; i >= 0; i-- { + switch s[i] { + case '}': + depth++ + case '{': + depth-- + if depth == 0 { + return strings.TrimSpace(s[i : end+1]), i, true + } + } + } + return "", 0, false +} + +// parseSourceToken splits "file:line" (basename may contain ':' on some platforms — last ':' wins). +func parseSourceToken(tok string) (file string, line int, ok bool) { + i := strings.LastIndex(tok, ":") + if i <= 0 || i == len(tok)-1 { + return "", 0, false + } + file = tok[:i] + n, err := strconv.Atoi(tok[i+1:]) + if err != nil { + return "", 0, false + } + return file, n, true +} From 39c325b7b89a35f37d09371cf337b4526ecc4e86 Mon Sep 17 00:00:00 2001 From: Chris Okuda Date: Sat, 28 Mar 2026 14:43:56 -1000 Subject: [PATCH 08/18] add better comments --- rlog/console/console.go | 23 +++++++++++++++-------- 1 file changed, 15 insertions(+), 8 deletions(-) diff --git a/rlog/console/console.go b/rlog/console/console.go index 6378c87..fe0676e 100644 --- a/rlog/console/console.go +++ b/rlog/console/console.go @@ -94,13 +94,15 @@ func (h *Handler) WithGroup(name string) slog.Handler { func (h *Handler) Handle(_ context.Context, r slog.Record) error { var buf bytes.Buffer - // Optional ReplaceAttr hook (nil group path for built-ins). + // ReplaceAttr (slog.HandlerOptions) can rename, drop, or rewrite built-in keys before we render. + // Built-ins use a nil group path, matching slog's convention for top-level keys. var repl func([]string, slog.Attr) slog.Attr if h.opts.HandlerOptions != nil { repl = h.opts.ReplaceAttr } - // Time + // Time: normalize to UTC when requested, build a TimeKey attr, then run ReplaceAttr so output + // can omit or alter the timestamp without changing r.Time itself. tm := r.Time if h.opts.UTCTime { tm = tm.UTC() @@ -113,19 +115,20 @@ func (h *Handler) Handle(_ context.Context, r slog.Record) error { } } - // Level + // Level: wrap the record level as LevelKey and pass through ReplaceAttr (e.g. custom labels). levelAttr := slog.Any(slog.LevelKey, r.Level) if repl != nil { levelAttr = repl(nil, levelAttr) } - // Message + // Message: wrap r.Message as MessageKey and pass through ReplaceAttr. msgAttr := slog.String(slog.MessageKey, r.Message) if repl != nil { msgAttr = repl(nil, msgAttr) } - // Source (optional) + // Source: when AddSource is on and the record has a PC, build SourceKey and allow ReplaceAttr + // to strip it (empty attr). If still present, emit file:line before the rest of the prefix. showSource := false var srcAttr slog.Attr if h.opts.HandlerOptions != nil && h.opts.AddSource && r.PC != 0 { @@ -141,6 +144,7 @@ func (h *Handler) Handle(_ context.Context, r slog.Record) error { writeSourcePrefix(&buf, h.opts.NoColor, srcAttr) } + // Prefix: bracketed time (light gray) when ReplaceAttr left a non-zero time value. if !timeAttr.Equal(slog.Attr{}) && timeAttr.Value.Kind() == slog.KindTime && !timeAttr.Value.Time().IsZero() { tm2 := timeAttr.Value.Time() if h.opts.UTCTime { @@ -150,6 +154,7 @@ func (h *Handler) Handle(_ context.Context, r slog.Record) error { buf.WriteRune(' ') } + // Level string and optional ANSI color, then a separator space before the message. lv := levelForOutput(levelAttr, r.Level) level := lv.String() + ":" if code, ok := levelANSICode(lv); h.opts.NoColor || !ok { @@ -160,13 +165,15 @@ func (h *Handler) Handle(_ context.Context, r slog.Record) error { buf.WriteRune(' ') + // Message: use ReplaceAttr's string if still valid; otherwise fall back to r.Message. msg := r.Message if !msgAttr.Equal(slog.Attr{}) && msgAttr.Value.Kind() == slog.KindString { msg = msgAttr.Value.String() } writePlainOrColor(&buf, h.opts.NoColor, white, msg) - // User attrs: collect record fields (skip duplicates of built-ins), merge With/WithGroup stack. + // User attributes: everything on the record except the built-in keys (already shown in the prefix), + // merged with handler-scoped attrs from WithAttrs / WithGroup. var recAttrs []slog.Attr r.Attrs(func(a slog.Attr) bool { if a.Key == slog.LevelKey || a.Key == slog.MessageKey || a.Key == slog.TimeKey { @@ -177,7 +184,7 @@ func (h *Handler) Handle(_ context.Context, r slog.Record) error { }) merged := buildMergedUserAttrs(h.topAttrs, h.segments, recAttrs) - // Trailing JSON object (compact or indented), or newline only when NoJSON. + // Trailer: one JSON object (Encode adds a trailing newline) or plain newline when NoJSON. if !h.opts.NoJSON { buf.WriteRune(' ') attrs := make(map[string]any) @@ -195,7 +202,7 @@ func (h *Handler) Handle(_ context.Context, r slog.Record) error { buf.WriteRune('\n') } - // One write per record, serialized with sibling handlers sharing this mutex. + // Single Write call per log line; mu coordinates output when multiple handlers share one writer. h.mu.Lock() defer h.mu.Unlock() _, err := h.w.Write(buf.Bytes()) From ce6731568ef97913133482ca84df0c4cf4f92d2b Mon Sep 17 00:00:00 2001 From: Chris Okuda Date: Sat, 28 Mar 2026 14:48:54 -1000 Subject: [PATCH 09/18] do the custom levels for the tests but also test one LEVEL-N level --- rlog/console/console_test.go | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/rlog/console/console_test.go b/rlog/console/console_test.go index dbc6fa1..3e40964 100644 --- a/rlog/console/console_test.go +++ b/rlog/console/console_test.go @@ -60,7 +60,7 @@ func TestHandler_GoldenTest(t *testing.T) { { name: "Trace", opts: &console.Options{HandlerOptions: &slog.HandlerOptions{Level: rlog.LevelTrace}}, - want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[37mDEBUG-4:\x1b[0m \x1b[97mtracing\x1b[0m {\"req\":{\"foo\":\"bar\",\"id\":\"1\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[36mDEBUG:\x1b[0m \x1b[97mdebugging\x1b[0m {\"req\":{\"foo\":\"bar\",\"id\":\"1\",\"user\":\"bob\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\"req\":{\"foo\":\"bar\",\"id\":\"1\",\"user\":\"alice\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\"req\":{\"code\":404,\"error\":\"not found\",\"id\":\"1\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\"req\":{\"code\":400,\"error\":\"uncapped jar\",\"id\":\"1\"},\"svc\":\"api\"}\n"), + want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[37mDEBUG-4:\x1b[0m \x1b[97mtracing\x1b[0m {\"req\":{\"foo\":\"bar\",\"id\":\"1\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m DEBUG-3: \x1b[97mtrace+1\x1b[0m {\"req\":{\"id\":\"1\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[36mDEBUG:\x1b[0m \x1b[97mdebugging\x1b[0m {\"req\":{\"foo\":\"bar\",\"id\":\"1\",\"user\":\"bob\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\"req\":{\"foo\":\"bar\",\"id\":\"1\",\"user\":\"alice\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\"req\":{\"code\":404,\"error\":\"not found\",\"id\":\"1\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\"req\":{\"code\":400,\"error\":\"uncapped jar\",\"id\":\"1\"},\"svc\":\"api\"}\n"), }, } @@ -72,12 +72,14 @@ func TestHandler_GoldenTest(t *testing.T) { if opts == nil { opts = &console.Options{} } + opts.HandlerOptions = rlog.MergeWithCustomLevels(opts.HandlerOptions) opts.UTCTime = true base := rlog.New(slog.New(console.New(&buf, opts))) log := base.With(slog.String("svc", "api")).WithGroup("req").With(slog.String("id", "1")) ctx := context.Background() log.TraceAttrs(ctx, "tracing", slog.String("foo", "bar")) + log.Log(ctx, rlog.LevelTrace+1, "trace+1") log.DebugAttrs(ctx, "debugging", slog.String("foo", "bar"), slog.String("user", "bob")) log.InfoAttrs(ctx, "info", slog.String("foo", "bar"), slog.String("user", "alice")) log.WarnAttrs(ctx, "warning", slog.String("error", "not found"), slog.Int("code", 404)) From dc5a130299b4dfb942bad10ba1daa70ae2e42adb Mon Sep 17 00:00:00 2001 From: Chris Okuda Date: Sat, 28 Mar 2026 14:51:33 -1000 Subject: [PATCH 10/18] add demo --- rlog/console/cmd/main.go | 108 +++++++++++++++++++++++++++++++++++++++ rlog/console/console.go | 2 + 2 files changed, 110 insertions(+) create mode 100644 rlog/console/cmd/main.go diff --git a/rlog/console/cmd/main.go b/rlog/console/cmd/main.go new file mode 100644 index 0000000..d17ae85 --- /dev/null +++ b/rlog/console/cmd/main.go @@ -0,0 +1,108 @@ +// Command console demonstrates [console.Handler] and every [console.Options] field. +package main + +import ( + "context" + "fmt" + "log/slog" + "os" + "time" + + "go.rtnl.ai/x/rlog" + "go.rtnl.ai/x/rlog/console" +) + +func main() { + ctx := context.Background() + + banner("nil *Options (handler defaults: INFO min, color, compact JSON, local time)") + log := slog.New(console.New(os.Stdout, nil)) + sample(ctx, log) + + banner("explicit defaults: &console.Options{}") + log = slog.New(console.New(os.Stdout, &console.Options{})) + sample(ctx, log) + + banner("NoColor: plain text, no ANSI") + log = slog.New(console.New(os.Stdout, &console.Options{NoColor: true})) + sample(ctx, log) + + banner("IndentJSON: multi-line JSON trailer") + log = slog.New(console.New(os.Stdout, &console.Options{IndentJSON: true})) + sample(ctx, log) + + banner("NoJSON: message only, newline (no attribute object)") + log = slog.New(console.New(os.Stdout, &console.Options{NoJSON: true})) + sample(ctx, log) + + banner("UTCTime: bracketed clock in UTC") + log = slog.New(console.New(os.Stdout, &console.Options{UTCTime: true})) + log.Info("server tick", "tz", "expect UTC in prefix") + + banner("HandlerOptions.Level: floor at TRACE (debug/trace on; FATAL/PANIC severities)") + hOpts := &slog.HandlerOptions{Level: rlog.LevelTrace} + log = slog.New(console.New(os.Stdout, &console.Options{HandlerOptions: hOpts})) + log.Log(ctx, rlog.LevelTrace, "trace line") + log.Debug("debug line") + log.Info("info line") + log.Log(ctx, rlog.LevelFatal, "fatal line (logged only; no exit)") + log.Log(ctx, rlog.LevelPanic, "panic line (logged only; no panic)") + + banner("HandlerOptions.AddSource: basename:line before timestamp") + log = slog.New(console.New(os.Stdout, &console.Options{ + HandlerOptions: &slog.HandlerOptions{AddSource: true}, + })) + log.Info("called from main with AddSource") + + banner("HandlerOptions.ReplaceAttr: drop secrets, custom time/message (with MergeWithCustomLevels)") + customReplace := func(groups []string, a slog.Attr) slog.Attr { + if a.Key == "secret" { + return slog.Attr{} + } + if len(groups) == 0 && a.Key == slog.MessageKey { + return slog.String(slog.MessageKey, "[wrapped] "+a.Value.String()) + } + return a + } + base := &slog.HandlerOptions{ + Level: slog.LevelDebug, + AddSource: true, + ReplaceAttr: customReplace, + } + log = slog.New(console.New(os.Stdout, &console.Options{ + HandlerOptions: rlog.MergeWithCustomLevels(base), + NoColor: true, + IndentJSON: true, + UTCTime: true, + })) + log.Info("replace attr demo", "secret", "hunter2", "public", "ok") + log.Log(ctx, rlog.LevelTrace, "trace after MergeWithCustomLevels (level key still renders as slog level string)") + + banner("WithAttrs / WithGroup on logger") + log = slog.New(console.New(os.Stdout, &console.Options{IndentJSON: true})). + With("service", "demo"). + WithGroup("http"). + With(slog.String("method", "GET")) + log.Info("grouped request", slog.String("path", "/v1/status"), "status", 200) + + banner("JSON trailer: times, durations, and nested maps in attrs") + log = slog.New(console.New(os.Stdout, &console.Options{IndentJSON: true})) + log.Info("mixed value kinds in JSON", + slog.Time("when", time.Now()), + slog.Duration("elapsed", 123*time.Millisecond), + slog.Any("nested", map[string]int{"a": 1}), + ) +} + +func banner(title string) { + fmt.Println() + fmt.Println("---", title, "---") +} + +func sample(ctx context.Context, log *slog.Logger) { + log.Debug("filtered at default INFO minimum") + log.Info("hello console", "count", 3, "ok", true) + log.Warn("something odd", slog.Duration("wait", 50*time.Millisecond)) + log.Error("failed", "err", "boom", "code", 500) + log.Log(ctx, rlog.LevelTrace, "also filtered unless Level is lowered") +} diff --git a/rlog/console/console.go b/rlog/console/console.go index fe0676e..63dda2e 100644 --- a/rlog/console/console.go +++ b/rlog/console/console.go @@ -1,5 +1,7 @@ // Package console implements a [slog.Handler] that pretty-prints log lines with optional colors // and a trailing JSON object of attributes. For development and tests, not high-throughput logging. +// +// The command `go run ./rlog/console/cmd/` gives a demo of the handler with various options. package console import ( From b89967ac181469189652ae3cd38faf8ba50eaf9d Mon Sep 17 00:00:00 2001 From: Chris Okuda Date: Sat, 28 Mar 2026 15:24:10 -1000 Subject: [PATCH 11/18] update source to bracket it --- rlog/console/cmd/main.go | 2 +- rlog/console/console.go | 25 +++++++++++++++++++------ rlog/console/console_test.go | 8 +++++--- rlog/console/parse.go | 6 +++--- 4 files changed, 28 insertions(+), 13 deletions(-) diff --git a/rlog/console/cmd/main.go b/rlog/console/cmd/main.go index d17ae85..226807a 100644 --- a/rlog/console/cmd/main.go +++ b/rlog/console/cmd/main.go @@ -48,7 +48,7 @@ func main() { log.Log(ctx, rlog.LevelFatal, "fatal line (logged only; no exit)") log.Log(ctx, rlog.LevelPanic, "panic line (logged only; no panic)") - banner("HandlerOptions.AddSource: basename:line before timestamp") + banner("HandlerOptions.AddSource: [basename:line] before timestamp") log = slog.New(console.New(os.Stdout, &console.Options{ HandlerOptions: &slog.HandlerOptions{AddSource: true}, })) diff --git a/rlog/console/console.go b/rlog/console/console.go index 63dda2e..948a74c 100644 --- a/rlog/console/console.go +++ b/rlog/console/console.go @@ -20,7 +20,7 @@ import ( const timeFormat = "[15:04:05.000]" -// Handler writes a text prefix (source, time, level, message) and optional JSON attributes. +// Handler writes a text prefix ([basename:line] when AddSource, bracketed time, level, message) and optional JSON attributes. type Handler struct { w io.Writer mu *sync.Mutex @@ -130,7 +130,7 @@ func (h *Handler) Handle(_ context.Context, r slog.Record) error { } // Source: when AddSource is on and the record has a PC, build SourceKey and allow ReplaceAttr - // to strip it (empty attr). If still present, emit file:line before the rest of the prefix. + // to strip it (empty attr). If still present, emit [basename:line] before the rest of the prefix. showSource := false var srcAttr slog.Attr if h.opts.HandlerOptions != nil && h.opts.AddSource && r.PC != 0 { @@ -156,9 +156,21 @@ func (h *Handler) Handle(_ context.Context, r slog.Record) error { buf.WriteRune(' ') } - // Level string and optional ANSI color, then a separator space before the message. + // Level prefix: when ReplaceAttr rewrites [slog.LevelKey] to a string (e.g. TRACE via + // [rlog.MergeWithCustomLevels]), print that text plus ":" so the line matches other + // handlers; otherwise use [slog.Level.String] from levelForOutput. ANSI color still + // uses the resolved [slog.Level] (lv), not the string label. lv := levelForOutput(levelAttr, r.Level) - level := lv.String() + ":" + var level string + if levelAttr.Key == slog.LevelKey && !levelAttr.Equal(slog.Attr{}) && levelAttr.Value.Kind() == slog.KindString { + if s := levelAttr.Value.String(); s != "" { + level = s + ":" + } else { + level = lv.String() + ":" + } + } else { + level = lv.String() + ":" + } if code, ok := levelANSICode(lv); h.opts.NoColor || !ok { fmt.Fprint(&buf, level) } else { @@ -220,7 +232,7 @@ func writePlainOrColor(buf *bytes.Buffer, noColor bool, color uint8, text string } } -// writeSourcePrefix prints basename:line when srcAttr carries *slog.Source. +// writeSourcePrefix prints [basename:line] when srcAttr carries *slog.Source (same bracket style as time). func writeSourcePrefix(buf *bytes.Buffer, noColor bool, srcAttr slog.Attr) { if srcAttr.Value.Kind() != slog.KindAny { return @@ -229,7 +241,8 @@ func writeSourcePrefix(buf *bytes.Buffer, noColor bool, srcAttr slog.Attr) { if !ok || s == nil || (s.File == "" && s.Line == 0) { return } - writePlainOrColor(buf, noColor, lightGray, fmt.Sprintf("%s:%d ", filepath.Base(s.File), s.Line)) + writePlainOrColor(buf, noColor, lightGray, fmt.Sprintf("[%s:%d]", filepath.Base(s.File), s.Line)) + buf.WriteRune(' ') } // levelForOutput prefers a slog.Level inside levelAttr after ReplaceAttr. diff --git a/rlog/console/console_test.go b/rlog/console/console_test.go index 3e40964..184ddc1 100644 --- a/rlog/console/console_test.go +++ b/rlog/console/console_test.go @@ -4,6 +4,7 @@ import ( "bytes" "context" "log/slog" + "regexp" "runtime" "strings" "testing" @@ -60,7 +61,7 @@ func TestHandler_GoldenTest(t *testing.T) { { name: "Trace", opts: &console.Options{HandlerOptions: &slog.HandlerOptions{Level: rlog.LevelTrace}}, - want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[37mDEBUG-4:\x1b[0m \x1b[97mtracing\x1b[0m {\"req\":{\"foo\":\"bar\",\"id\":\"1\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m DEBUG-3: \x1b[97mtrace+1\x1b[0m {\"req\":{\"id\":\"1\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[36mDEBUG:\x1b[0m \x1b[97mdebugging\x1b[0m {\"req\":{\"foo\":\"bar\",\"id\":\"1\",\"user\":\"bob\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\"req\":{\"foo\":\"bar\",\"id\":\"1\",\"user\":\"alice\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\"req\":{\"code\":404,\"error\":\"not found\",\"id\":\"1\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\"req\":{\"code\":400,\"error\":\"uncapped jar\",\"id\":\"1\"},\"svc\":\"api\"}\n"), + want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[37mTRACE:\x1b[0m \x1b[97mtracing\x1b[0m {\"req\":{\"foo\":\"bar\",\"id\":\"1\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m DEBUG-3: \x1b[97mtrace+1\x1b[0m {\"req\":{\"id\":\"1\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[36mDEBUG:\x1b[0m \x1b[97mdebugging\x1b[0m {\"req\":{\"foo\":\"bar\",\"id\":\"1\",\"user\":\"bob\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\"req\":{\"foo\":\"bar\",\"id\":\"1\",\"user\":\"alice\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\"req\":{\"code\":404,\"error\":\"not found\",\"id\":\"1\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\"req\":{\"code\":400,\"error\":\"uncapped jar\",\"id\":\"1\"},\"svc\":\"api\"}\n"), }, } @@ -166,7 +167,7 @@ func TestHandler_ReplaceAttr_dropsKey(t *testing.T) { }) } -// TestHandler_AddSource_prefix ensures AddSource adds a basename:line prefix and ParseLogLine exposes +// TestHandler_AddSource_prefix ensures AddSource adds a [basename:line] prefix and ParseLogLine exposes // [slog.SourceKey] with File and Line when Handle receives a record built with a non-zero PC. func TestHandler_AddSource_prefix(t *testing.T) { synctest.Test(t, func(t *testing.T) { @@ -185,7 +186,8 @@ func TestHandler_AddSource_prefix(t *testing.T) { assert.Ok(t, h.Handle(context.Background(), r), "Handle with AddSource should not error") line := strings.TrimSpace(buf.String()) - assert.True(t, strings.Contains(line, ":"), "AddSource should print file:line before the rest of the line; got %q", line) + assert.True(t, regexp.MustCompile(`^\[[^\]]+:\d+\]\s+`).MatchString(line), + "AddSource should print [basename:line] before the rest of the line; got %q", line) m, err := console.ParseLogLine(line) assert.Ok(t, err, "line with source prefix should parse") diff --git a/rlog/console/parse.go b/rlog/console/parse.go index e90f71d..afdf324 100644 --- a/rlog/console/parse.go +++ b/rlog/console/parse.go @@ -11,10 +11,10 @@ import ( "time" ) -// Line layout: optional source, optional [HH:MM:SS.mmm], LEVEL: message [JSON]. +// Line layout: optional [basename:line], optional [HH:MM:SS.mmm], LEVEL: message [JSON]. var ( ansiRegexp = regexp.MustCompile(`\x1b\[[0-9;]*m`) - sourcePrefixRx = regexp.MustCompile(`^([^\s]+:\d+)\s+`) + sourcePrefixRx = regexp.MustCompile(`^\[([^\]]+:\d+)\]\s+`) timeBracketRx = regexp.MustCompile(`^\[(\d{2}:\d{2}:\d{2}\.\d{3})\]\s+`) levelPrefixRx = regexp.MustCompile(`^([A-Za-z0-9+-]+):\s+`) ) @@ -29,7 +29,7 @@ func ParseLogLine(line string) (map[string]any, error) { m := make(map[string]any) - // Parse optional source:line. + // Parse optional [basename:line] (bracketed like the time prefix). if sm := sourcePrefixRx.FindStringSubmatch(s); sm != nil { file, lineNum, ok := parseSourceToken(sm[1]) if ok { From 3e54919bb3a0e980ed7a454e7454794575c69467 Mon Sep 17 00:00:00 2001 From: Chris Okuda Date: Sat, 28 Mar 2026 19:22:00 -1000 Subject: [PATCH 12/18] mirror [slog.Level] levels --- rlog/level.go | 22 +++++++++++++--------- 1 file changed, 13 insertions(+), 9 deletions(-) diff --git a/rlog/level.go b/rlog/level.go index fb58785..efb9b70 100644 --- a/rlog/level.go +++ b/rlog/level.go @@ -14,11 +14,15 @@ const ( LevelTrace slog.Level = slog.LevelDebug - 4 LevelTraceKey string = "TRACE" - // [slog.Level] keys (unavailable from slog package) - LevelDebugKey string = "DEBUG" // for [slog.LevelDebug] - LevelInfoKey string = "INFO" // for [slog.LevelInfo] - LevelWarnKey string = "WARN" // for [slog.LevelWarn] - LevelErrorKey string = "ERROR" // for [slog.LevelError] + // Mirrors [slog.Level] and adds keys + LevelDebug slog.Level = slog.LevelDebug + LevelDebugKey string = "DEBUG" // for [slog.LevelDebug] + LevelInfo slog.Level = slog.LevelInfo + LevelInfoKey string = "INFO" // for [slog.LevelInfo] + LevelWarn slog.Level = slog.LevelWarn + LevelWarnKey string = "WARN" // for [slog.LevelWarn] + LevelError slog.Level = slog.LevelError + LevelErrorKey string = "ERROR" // for [slog.LevelError] // LevelFatal is more severe than [slog.LevelError]. LevelFatal slog.Level = slog.LevelError + 4 @@ -70,13 +74,13 @@ func (ll LevelDecoder) Encode() (string, error) { switch slog.Level(ll) { case LevelTrace: return LevelTraceKey, nil - case slog.LevelDebug: + case LevelDebug: return LevelDebugKey, nil - case slog.LevelInfo: + case LevelInfo: return LevelInfoKey, nil - case slog.LevelWarn: + case LevelWarn: return LevelWarnKey, nil - case slog.LevelError: + case LevelError: return LevelErrorKey, nil case LevelFatal: return LevelFatalKey, nil From db846b0005451769d23fc72d5e502212687a67da Mon Sep 17 00:00:00 2001 From: Chris Okuda Date: Sat, 28 Mar 2026 19:42:49 -1000 Subject: [PATCH 13/18] improved the example command to be more consistent and added a simple way to merge rlog custom levels into a console.Options and optimised that merge --- rlog/console/cmd/main.go | 160 ++++++++++++++++++++------------------- rlog/console/options.go | 21 ++++- rlog/options.go | 14 ++-- 3 files changed, 109 insertions(+), 86 deletions(-) diff --git a/rlog/console/cmd/main.go b/rlog/console/cmd/main.go index 226807a..93c67cb 100644 --- a/rlog/console/cmd/main.go +++ b/rlog/console/cmd/main.go @@ -1,8 +1,8 @@ -// Command console demonstrates [console.Handler] and every [console.Options] field. +// Command console demonstrates [console.Handler] and [console.Options] through +// [rlog.Logger], including custom levels (TRACE, FATAL, PANIC). package main import ( - "context" "fmt" "log/slog" "os" @@ -13,96 +13,100 @@ import ( ) func main() { - ctx := context.Background() - - banner("nil *Options (handler defaults: INFO min, color, compact JSON, local time)") - log := slog.New(console.New(os.Stdout, nil)) - sample(ctx, log) - - banner("explicit defaults: &console.Options{}") - log = slog.New(console.New(os.Stdout, &console.Options{})) - sample(ctx, log) - - banner("NoColor: plain text, no ANSI") - log = slog.New(console.New(os.Stdout, &console.Options{NoColor: true})) - sample(ctx, log) - - banner("IndentJSON: multi-line JSON trailer") - log = slog.New(console.New(os.Stdout, &console.Options{IndentJSON: true})) - sample(ctx, log) - - banner("NoJSON: message only, newline (no attribute object)") - log = slog.New(console.New(os.Stdout, &console.Options{NoJSON: true})) - sample(ctx, log) - - banner("UTCTime: bracketed clock in UTC") - log = slog.New(console.New(os.Stdout, &console.Options{UTCTime: true})) - log.Info("server tick", "tz", "expect UTC in prefix") - - banner("HandlerOptions.Level: floor at TRACE (debug/trace on; FATAL/PANIC severities)") - hOpts := &slog.HandlerOptions{Level: rlog.LevelTrace} - log = slog.New(console.New(os.Stdout, &console.Options{HandlerOptions: hOpts})) - log.Log(ctx, rlog.LevelTrace, "trace line") - log.Debug("debug line") - log.Info("info line") - log.Log(ctx, rlog.LevelFatal, "fatal line (logged only; no exit)") - log.Log(ctx, rlog.LevelPanic, "panic line (logged only; no panic)") - - banner("HandlerOptions.AddSource: [basename:line] before timestamp") - log = slog.New(console.New(os.Stdout, &console.Options{ - HandlerOptions: &slog.HandlerOptions{AddSource: true}, - })) - log.Info("called from main with AddSource") - - banner("HandlerOptions.ReplaceAttr: drop secrets, custom time/message (with MergeWithCustomLevels)") - customReplace := func(groups []string, a slog.Attr) slog.Attr { - if a.Key == "secret" { - return slog.Attr{} + // Fatal would normally exit; keep the demo running through all sections. + rlog.SetFatalHook(func() {}) + defer rlog.SetFatalHook(nil) + + // One pattern everywhere: banner → newConsole(opts) → standardDemo (optional extra / derive). + run := func(title string, opts *console.Options, extra func(log *rlog.Logger)) { + banner(title) + log := newConsole(opts) + standardDemo(log) + if extra != nil { + extra(log) } - if len(groups) == 0 && a.Key == slog.MessageKey { - return slog.String(slog.MessageKey, "[wrapped] "+a.Value.String()) - } - return a } - base := &slog.HandlerOptions{ - Level: slog.LevelDebug, - AddSource: true, - ReplaceAttr: customReplace, + runDerived := func(title string, opts *console.Options, derive func(*rlog.Logger) *rlog.Logger, extra func(log *rlog.Logger)) { + banner(title) + log := derive(newConsole(opts)) + standardDemo(log) + if extra != nil { + extra(log) + } } - log = slog.New(console.New(os.Stdout, &console.Options{ - HandlerOptions: rlog.MergeWithCustomLevels(base), - NoColor: true, - IndentJSON: true, - UTCTime: true, - })) - log.Info("replace attr demo", "secret", "hunter2", "public", "ok") - log.Log(ctx, rlog.LevelTrace, "trace after MergeWithCustomLevels (level key still renders as slog level string)") - banner("WithAttrs / WithGroup on logger") - log = slog.New(console.New(os.Stdout, &console.Options{IndentJSON: true})). - With("service", "demo"). - WithGroup("http"). - With(slog.String("method", "GET")) - log.Info("grouped request", slog.String("path", "/v1/status"), "status", 200) + run("nil *Options — defaults: INFO floor, color, compact JSON, local time", nil, nil) + + run("NoJSON — message only, no attribute object", &console.Options{NoJSON: true}, nil) + + run("HandlerOptions.Level — TRACE floor (debug/trace on)", + &console.Options{HandlerOptions: &slog.HandlerOptions{Level: rlog.LevelTrace}}, nil) + + run("HandlerOptions.AddSource — [file:line] before timestamp", + &console.Options{HandlerOptions: &slog.HandlerOptions{AddSource: true}}, nil) + + run("ReplaceAttr + NoColor + UTCTime — drop keys, wrap message; plain text, UTC clock", + &console.Options{ + HandlerOptions: &slog.HandlerOptions{ + Level: rlog.LevelTrace, + AddSource: true, + ReplaceAttr: replaceAttrDemo, + }, + NoColor: true, + UTCTime: true, + }, + func(log *rlog.Logger) { + log.Info("secrets redacted", "secret", "redacted", "public", "visible") + log.Trace("trace after merge") + }, + ) - banner("JSON trailer: times, durations, and nested maps in attrs") - log = slog.New(console.New(os.Stdout, &console.Options{IndentJSON: true})) - log.Info("mixed value kinds in JSON", - slog.Time("when", time.Now()), - slog.Duration("elapsed", 123*time.Millisecond), - slog.Any("nested", map[string]int{"a": 1}), + runDerived("IndentJSON — multi-line trailer; With / WithGroup; time, duration, maps", + &console.Options{IndentJSON: true}, + func(log *rlog.Logger) *rlog.Logger { + return log.With("service", "demo"). + WithGroup("http"). + With(slog.String("method", "GET")) + }, + func(log *rlog.Logger) { + log.Info("request", slog.String("path", "/v1/status"), "status", 200) + log.Info("structured attrs", + slog.Time("when", time.Now()), + slog.Duration("elapsed", 123*time.Millisecond), + slog.Any("nested", map[string]int{"a": 1}), + ) + }, ) } +func newConsole(opts *console.Options) *rlog.Logger { + return rlog.New(slog.New(console.New(os.Stdout, opts.MergeWithCustomLevels()))) +} + func banner(title string) { fmt.Println() fmt.Println("---", title, "---") } -func sample(ctx context.Context, log *slog.Logger) { - log.Debug("filtered at default INFO minimum") +func standardDemo(log *rlog.Logger) { + log.Trace("trace") + log.Debug("debug") log.Info("hello console", "count", 3, "ok", true) log.Warn("something odd", slog.Duration("wait", 50*time.Millisecond)) log.Error("failed", "err", "boom", "code", 500) - log.Log(ctx, rlog.LevelTrace, "also filtered unless Level is lowered") + log.Fatal("fatal") + func() { + defer func() { recover() }() + log.Panic("panic") + }() +} + +func replaceAttrDemo(groups []string, a slog.Attr) slog.Attr { + if a.Key == "secret" { + return slog.Attr{} + } + if len(groups) == 0 && a.Key == slog.MessageKey { + return slog.String(slog.MessageKey, "[wrapped] "+a.Value.String()) + } + return a } diff --git a/rlog/console/options.go b/rlog/console/options.go index 8abd880..1d0dfd4 100644 --- a/rlog/console/options.go +++ b/rlog/console/options.go @@ -1,6 +1,10 @@ package console -import "log/slog" +import ( + "log/slog" + + "go.rtnl.ai/x/rlog" +) // Options are used for the [console.Handler] a nil or zero valued Options consists // entirely of default values. @@ -20,3 +24,18 @@ type Options struct { // Marking true causes the handler to format the time using the UTC timezone. UTCTime bool } + +// MergeWithCustomLevels merges the options with the custom rlog.Level* keys. +// If o is nil, returns a new Options with the default values. +func (o *Options) MergeWithCustomLevels() *Options { + if o == nil { + o = &Options{} + } + return &Options{ + HandlerOptions: rlog.MergeWithCustomLevels(o.HandlerOptions), + NoColor: o.NoColor, + IndentJSON: o.IndentJSON, + NoJSON: o.NoJSON, + UTCTime: o.UTCTime, + } +} diff --git a/rlog/options.go b/rlog/options.go index 19f37a3..906c1e1 100644 --- a/rlog/options.go +++ b/rlog/options.go @@ -29,15 +29,15 @@ func MergeWithCustomLevels(opts *slog.HandlerOptions) *slog.HandlerOptions { merged = *opts } - next := merged.ReplaceAttr - merged.ReplaceAttr = func(groups []string, a slog.Attr) slog.Attr { - a = ReplaceLevelKey(groups, a) - - if next != nil { + // If ReplaceAttr is nil, set it to ReplaceLevelKey, otherwise chain it. + if merged.ReplaceAttr == nil { + merged.ReplaceAttr = ReplaceLevelKey + } else { + next := merged.ReplaceAttr + merged.ReplaceAttr = func(groups []string, a slog.Attr) slog.Attr { + a = ReplaceLevelKey(groups, a) return next(groups, a) } - - return a } return &merged From 10596f46d0bdebee2bdda2ea9cfe6664f9a6ede0 Mon Sep 17 00:00:00 2001 From: Chris Okuda Date: Sat, 28 Mar 2026 19:47:21 -1000 Subject: [PATCH 14/18] shorten demo --- rlog/console/cmd/main.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/rlog/console/cmd/main.go b/rlog/console/cmd/main.go index 93c67cb..0ab4a40 100644 --- a/rlog/console/cmd/main.go +++ b/rlog/console/cmd/main.go @@ -56,13 +56,13 @@ func main() { UTCTime: true, }, func(log *rlog.Logger) { - log.Info("secrets redacted", "secret", "redacted", "public", "visible") - log.Trace("trace after merge") + log.Info("'secret' key redacted", "secret", "NOT REDACTED!!!", "public", "visible") + log.Trace("trace after merge still uses rlog level string (TRACE)") }, ) - runDerived("IndentJSON — multi-line trailer; With / WithGroup; time, duration, maps", - &console.Options{IndentJSON: true}, + runDerived("IndentJSON — multi-line trailer; With / WithGroup; time, duration, maps; level Error", + &console.Options{IndentJSON: true, HandlerOptions: &slog.HandlerOptions{Level: rlog.LevelError}}, func(log *rlog.Logger) *rlog.Logger { return log.With("service", "demo"). WithGroup("http"). From 7db4538cb137a12aeeb83f8cc0380a2bfce759b1 Mon Sep 17 00:00:00 2001 From: Chris Okuda Date: Sat, 28 Mar 2026 21:02:56 -1000 Subject: [PATCH 15/18] Add benchmarks for rlog.Logger vs slog.Logger and enhance README documentation - Introduced `benchmark_test.go` to compare performance between `rlog.Logger` and `slog.Logger` with various logging scenarios. - Updated `README.md` to clarify module features, including new sections for `rlog.Logger`, subpackages, and usage examples. - Enhanced `rlog.go` with improved source attribution in logs. - Added tests to ensure correct source attribution in log records. --- rlog/README.md | 52 +++- rlog/benchmark_test.go | 451 +++++++++++++++++++++++++++++++++++ rlog/rlog.go | 522 +++++++++++++++++++++++++++-------------- rlog/rlog_test.go | 49 ++++ 4 files changed, 890 insertions(+), 184 deletions(-) create mode 100644 rlog/benchmark_test.go diff --git a/rlog/README.md b/rlog/README.md index 73f7420..0623c2e 100644 --- a/rlog/README.md +++ b/rlog/README.md @@ -1,20 +1,48 @@ # rlog -The `r` is for “Rotational”! This package extends [`log/slog`](https://pkg.go.dev/log/slog) with **Trace**, **Fatal**, and **Panic**, and helpers in the usual shapes (key/value, `*Context`, `*Attrs`). See [`go doc`](https://pkg.go.dev/go.rtnl.ai/x/rlog) for the full API. +The `r` is for “Rotational”! This module extends [`log/slog`](https://pkg.go.dev/log/slog) with **Trace**, **Fatal**, and **Panic**, options so those levels print with sensible names, and helpers to keep a global level in sync. The root package is [`go.rtnl.ai/x/rlog`](https://pkg.go.dev/go.rtnl.ai/x/rlog). Subpackages add a dev-friendly console handler, test capture helpers, and logging to multiple handlers at once. See [`go doc`](https://pkg.go.dev/go.rtnl.ai/x/rlog) and the subpackage docs for the full API. + +## `rlog.Logger` + +[`Logger`](https://pkg.go.dev/go.rtnl.ai/x/rlog#Logger) wraps [`*slog.Logger`](https://pkg.go.dev/log/slog#Logger) and adds **Trace**, **Fatal**, and **Panic** (with `Context` and `Attrs` variants), plus **DebugAttrs**, **InfoAttrs**, **WarnAttrs**, and **ErrorAttrs** for the built-in levels. [`New`](https://pkg.go.dev/go.rtnl.ai/x/rlog#New) builds one from an `*slog.Logger`; `nil` selects [`Default`](https://pkg.go.dev/go.rtnl.ai/x/rlog#Default). + +[`With`](https://pkg.go.dev/go.rtnl.ai/x/rlog#Logger.With) and [`WithGroup`](https://pkg.go.dev/go.rtnl.ai/x/rlog#Logger.WithGroup) behave like slog’s. Package-level helpers delegate to the default logger. - **Fatal** runs [`SetFatalHook`](https://pkg.go.dev/go.rtnl.ai/x/rlog#SetFatalHook) after logging if set; otherwise [`os.Exit(1)`](https://pkg.go.dev/os#Exit). **Panic** logs then panics with the message. -- [`MergeWithCustomLevels`](https://pkg.go.dev/go.rtnl.ai/x/rlog#MergeWithCustomLevels) maps custom levels to names `TRACE`, `FATAL`, `PANIC` in JSON/text output. [`ReplaceLevelKey`](https://pkg.go.dev/go.rtnl.ai/x/rlog#ReplaceLevelKey) does only the level mapping if you compose `ReplaceAttr` yourself. [`WithGlobalLevel`](https://pkg.go.dev/go.rtnl.ai/x/rlog#WithGlobalLevel) helps keep the global logging level synced. -- [`Logger.With`](https://pkg.go.dev/go.rtnl.ai/x/rlog#Logger.With) / [`WithGroup`](https://pkg.go.dev/go.rtnl.ai/x/rlog#Logger.WithGroup) keep a `*rlog.Logger` (same args as [`slog.Logger.With`](https://pkg.go.dev/log/slog#Logger.With)). Package-level [`With`](https://pkg.go.dev/go.rtnl.ai/x/rlog#With), [`WithGroup`](https://pkg.go.dev/go.rtnl.ai/x/rlog#WithGroup), [`Log`](https://pkg.go.dev/go.rtnl.ai/x/rlog#Log), and [`LogAttrs`](https://pkg.go.dev/go.rtnl.ai/x/rlog#LogAttrs) use the default logger. -- [`NewFanOut`](https://pkg.go.dev/go.rtnl.ai/x/rlog#NewFanOut) returns a [`slog.Handler`](https://pkg.go.dev/log/slog#Handler) that forwards each record to every child handler (multi-sink logging). -- [`NewCapturingTestHandler`](https://pkg.go.dev/go.rtnl.ai/x/rlog#NewCapturingTestHandler) helps tests capture records and JSON lines; pass `nil` or a [`testing.TB`](https://pkg.go.dev/testing#TB) to print test logs to the console. Helpers include [`ParseJSONLine`](https://pkg.go.dev/go.rtnl.ai/x/rlog#ParseJSONLine), [`ResultMaps`](https://pkg.go.dev/go.rtnl.ai/x/rlog#CapturingTestHandler.ResultMaps), and [`RecordsAndLines`](https://pkg.go.dev/go.rtnl.ai/x/rlog#CapturingTestHandler.RecordsAndLines) which returns a mutex-locked snapshot of current logs. -- [`LevelDecoder`](https://pkg.go.dev/go.rtnl.ai/x/rlog#LevelDecoder) parses level strings, including the added `TRACE`, `FATAL`, and `PANIC`. -## Default logger and Custom Handlers +## Package `rlog` (core) + +- [`MergeWithCustomLevels`](https://pkg.go.dev/go.rtnl.ai/x/rlog#MergeWithCustomLevels) labels custom severities as `TRACE`, `FATAL`, and `PANIC` in output. [`WithGlobalLevel`](https://pkg.go.dev/go.rtnl.ai/x/rlog#WithGlobalLevel) ties a handler’s threshold to [`SetLevel`](https://pkg.go.dev/go.rtnl.ai/x/rlog#SetLevel). [`ReplaceLevelKey`](https://pkg.go.dev/go.rtnl.ai/x/rlog#ReplaceLevelKey) is there if you build your own `ReplaceAttr` pipeline. +- [`LevelDecoder`](https://pkg.go.dev/go.rtnl.ai/x/rlog#LevelDecoder) parses level strings, including the extra severities. + +## Subpackage `console` + +[`go.rtnl.ai/x/rlog/console`](https://pkg.go.dev/go.rtnl.ai/x/rlog/console) provides a [`slog.Handler`](https://pkg.go.dev/log/slog#Handler) that prints **readable lines**: optional file/line, time, level (colors optional), message, and a JSON blob of attributes unless you turn that off. Meant for local dev and tests, not maximum throughput. + +[`console.New`](https://pkg.go.dev/go.rtnl.ai/x/rlog/console#New) and [`console.Options`](https://pkg.go.dev/go.rtnl.ai/x/rlog/console#Options) cover the usual slog options plus color, JSON layout, and UTC time. Use [`(*Options).MergeWithCustomLevels`](https://pkg.go.dev/go.rtnl.ai/x/rlog/console#Options.MergeWithCustomLevels) so TRACE/FATAL/PANIC match the rest of rlog. + +Demo from this repo: `go run ./rlog/console/cmd/`. + +## Subpackage `testing` + +[`go.rtnl.ai/x/rlog/testing`](https://pkg.go.dev/go.rtnl.ai/x/rlog/testing) — import with an alias (e.g. `rlogtesting "go.rtnl.ai/x/rlog/testing"`) so it does not clash with the standard [`testing`](https://pkg.go.dev/testing) package. + +[`NewCapturingTestHandler`](https://pkg.go.dev/go.rtnl.ai/x/rlog/testing#NewCapturingTestHandler) captures each log as JSON; pass `t` to also print lines in the test output, or `nil` for silent capture. Use [`Records`](https://pkg.go.dev/go.rtnl.ai/x/rlog/testing#CapturingTestHandler.Records), [`Lines`](https://pkg.go.dev/go.rtnl.ai/x/rlog/testing#CapturingTestHandler.Lines), [`RecordsAndLines`](https://pkg.go.dev/go.rtnl.ai/x/rlog/testing#CapturingTestHandler.RecordsAndLines), [`ResultMaps`](https://pkg.go.dev/go.rtnl.ai/x/rlog/testing#CapturingTestHandler.ResultMaps), and [`Reset`](https://pkg.go.dev/go.rtnl.ai/x/rlog/testing#CapturingTestHandler.Reset) in assertions. [`ParseJSONLine`](https://pkg.go.dev/go.rtnl.ai/x/rlog/testing#ParseJSONLine) / [`MustParseJSONLine`](https://pkg.go.dev/go.rtnl.ai/x/rlog/testing#MustParseJSONLine) help parse lines. + +Use [`rlog.New`](https://pkg.go.dev/go.rtnl.ai/x/rlog#New) on top when you need `*rlog.Logger` in tests. + +## Subpackage `fanout` + +[`go.rtnl.ai/x/rlog/fanout`](https://pkg.go.dev/go.rtnl.ai/x/rlog/fanout) sends **every log to every** child [`slog.Handler`](https://pkg.go.dev/log/slog#Handler). Build one with [`fanout.New`](https://pkg.go.dev/go.rtnl.ai/x/rlog/fanout#New). + +On **Go 1.26+**, use [`slog.MultiHandler`](https://pkg.go.dev/log/slog#MultiHandler) instead; this package covers the same idea on **Go 1.25 and earlier**. + +## Default logger and custom handlers -- The package default logs JSON to stdout at **Info**. -- [`SetDefault`](https://pkg.go.dev/go.rtnl.ai/x/rlog#SetDefault) replaces rlog’s global logger and updates [`slog.Default`](https://pkg.go.dev/log/slog#Default) via [`slog.SetDefault`](https://pkg.go.dev/log/slog#SetDefault). -- [`SetLevel`](https://pkg.go.dev/go.rtnl.ai/x/rlog#SetLevel), [`Level`](https://pkg.go.dev/go.rtnl.ai/x/rlog#Level), and [`LevelString`](https://pkg.go.dev/go.rtnl.ai/x/rlog#LevelString) read or set the shared [`slog.LevelVar`](https://pkg.go.dev/log/slog#LevelVar) wired into the default install. -- Handlers you build yourself should use `MergeWithCustomLevels(WithGlobalLevel(opts))` so they still honor that threshold after you call [`SetDefault`](https://pkg.go.dev/go.rtnl.ai/x/rlog#SetDefault); see [`WithGlobalLevel`](https://pkg.go.dev/go.rtnl.ai/x/rlog#WithGlobalLevel). +- Default: JSON on stdout at **Info**. +- [`SetDefault`](https://pkg.go.dev/go.rtnl.ai/x/rlog#SetDefault) replaces rlog’s default and keeps [`slog.Default`](https://pkg.go.dev/log/slog#Default) aligned. +- [`SetLevel`](https://pkg.go.dev/go.rtnl.ai/x/rlog#SetLevel), [`Level`](https://pkg.go.dev/go.rtnl.ai/x/rlog#Level), and [`LevelString`](https://pkg.go.dev/go.rtnl.ai/x/rlog#LevelString) control the default logger’s threshold. +- For your own handlers, combine `MergeWithCustomLevels` and `WithGlobalLevel` so they respect the same global level after `SetDefault` (see [`WithGlobalLevel`](https://pkg.go.dev/go.rtnl.ai/x/rlog#WithGlobalLevel)). ## Example @@ -48,7 +76,7 @@ func main() { // Without a hook, Fatal would os.Exit(1) and the rest of main would not run. rlog.SetFatalHook(func() {}) // demo only — replace with test hook or omit in production - defer rlog.SetFatalHook(nil) // setting the fatal hook to nil causes future Fatal calls to use os.Exit(1) + defer rlog.SetFatalHook(nil) log.Fatal("fatal-msg") // Output example: {"time":"…","level":"FATAL","msg":"fatal-msg"} — then runs the fatal hook (no exit here) diff --git a/rlog/benchmark_test.go b/rlog/benchmark_test.go new file mode 100644 index 0000000..2390393 --- /dev/null +++ b/rlog/benchmark_test.go @@ -0,0 +1,451 @@ +package rlog_test + +import ( + "context" + "fmt" + "log/slog" + "math" + "runtime" + "testing" + "time" + + "go.rtnl.ai/x/rlog" +) + +// BenchmarkLoggerVsSlog compares *rlog.Logger with *slog.Logger on identical nop handlers. +// +// # What every logging sub-benchmark measures +// +// Each “slog/…” and “rlog/…” pair uses the same [nopHandler]: Enabled always true, Handle a no-op. +// So the cost is almost entirely: capture caller PC (when applicable), build [slog.Record], merge +// attrs, dispatch to Handle—no I/O, no JSON, no locks in the handler. +// +// Sub-benchmark names: +// - LogAttrs-none — LogAttrs with message only (no extra attributes). +// - Info-kv — Info with one string key and int value ("a", 1). +// - Log-kv — Log with the same key/value pair. +// - *+pollute — same as above, but each iteration calls [benchPolluteCache] first (full rationale +// in the helpers section under “Cache pollution”). +// - paired/Info-kv-interleaved — one slog.Info then one rlog.Info per b.N iteration; ns/op is time +// for both calls together (not per logger). Useful to see both code paths in one hot loop. +// - rlog/Trace-none — custom TRACE level (no slog analogue with the same name). +// - runtime.Callers/skip2 — isolated cost of Callers(2), matching rlog’s wrapper depth. +// - runtime.Callers/skip3 — isolated cost of Callers(3), matching slog.Logger.log’s depth. +// - directHandle-pc0 — NewRecord + Handle with PC=0, no Callers (rough lower bound if source were free). +// +// # Why rlog can look faster than slog in the plain pairs +// +// Back-to-back sub-benchmarks are separate [testing.Benchmark] timing windows. The second side +// often hits warmer I-cache and branch history. rlog also uses Callers(2) at its API vs slog’s +// Callers(3) inside log—not identical work. So “rlog faster” on an isolated pair is not proof the +// wrapper is free; use [TestLoggerVsSlogCompare] or *+pollute for a less misleading picture. +// +// # How to run +// +// Skip other tests (avoids concurrent tests printing JSON and competing for CPU): +// +// go test -run=^$ -bench=BenchmarkLoggerVsSlog -benchmem ./rlog +// +// Percentage summary (slower/faster), with order averaging and a polluted section: +// +// go test ./rlog -run TestLoggerVsSlogCompare -v +// +// rlog cannot use [log/slog/internal.IgnorePC] (stdlib-only); slog’s -nopc benchmark flag does not apply here. +func BenchmarkLoggerVsSlog(b *testing.B) { + b.Run("slog/LogAttrs-none", benchSlogLogAttrsNone) + b.Run("rlog/LogAttrs-none", benchRlogLogAttrsNone) + b.Run("slog/Info-kv", benchSlogInfoKV) + b.Run("rlog/Info-kv", benchRlogInfoKV) + b.Run("slog/Log-kv", benchSlogLogKV) + b.Run("rlog/Log-kv", benchRlogLogKV) + b.Run("slog/LogAttrs-none+pollute", benchSlogLogAttrsNonePollute) + b.Run("rlog/LogAttrs-none+pollute", benchRlogLogAttrsNonePollute) + b.Run("slog/Info-kv+pollute", benchSlogInfoKVPollute) + b.Run("rlog/Info-kv+pollute", benchRlogInfoKVPollute) + b.Run("slog/Log-kv+pollute", benchSlogLogKVPollute) + b.Run("rlog/Log-kv+pollute", benchRlogLogKVPollute) + b.Run("paired/Info-kv-interleaved", benchPairedInfoKVInterleaved) + b.Run("rlog/Trace-none", benchRlogTraceNone) + b.Run("runtime.Callers/skip2", benchRuntimeCallersSkip2) + b.Run("runtime.Callers/skip3", benchRuntimeCallersSkip3) + b.Run("directHandle-pc0", benchDirectHandlePC0) +} + +// TestLoggerVsSlogCompare runs the same benchmark bodies as [BenchmarkLoggerVsSlog] and prints +// how much slower or faster rlog is versus slog as a percentage of slog’s ns/op. +// +// # Why not just compare two bench outputs by hand? +// +// A single run of “slog bench then rlog bench” biases whoever runs second (hotter caches for that +// binary path). This test uses [nsPerOpOrderAvg] for each pair: it runs slog→rlog, then rlog→slog, +// and averages each side’s ns/op so neither implementation always benefits from running after the other. +// +// # Two sections: isolated vs +pollute +// +// The first block is the plain benchmarks (tight loop, log call only). The second block uses the +// *+pollute functions: before each log call they run [benchPolluteCache] to touch a large, strided +// region of memory. That makes “everything fits in L1 and stays hot” less likely and often widens +// the gap when one path does more work (e.g. extra indirection in rlog). It still does not simulate +// real app contention; it is only a harsher microbench knob. +// +// # Baselines +// +// The final lines log rlog-only and PC-only benchmarks so you can sanity-check Callers cost vs full log. +// +// Skipped under -short (this test runs many benchmarks and can take tens of seconds). +// Run: go test ./rlog -run TestLoggerVsSlogCompare -v +func TestLoggerVsSlogCompare(t *testing.T) { + if testing.Short() { + t.Skip("skip bench comparison in -short") + } + + pairs := []struct { + name string + slogFn func(*testing.B) + rlogFn func(*testing.B) + }{ + {"LogAttrs-none", benchSlogLogAttrsNone, benchRlogLogAttrsNone}, + {"Info-kv", benchSlogInfoKV, benchRlogInfoKV}, + {"Log-kv", benchSlogLogKV, benchRlogLogKV}, + } + pairsPollute := []struct { + name string + slogFn func(*testing.B) + rlogFn func(*testing.B) + }{ + {"LogAttrs-none+pollute", benchSlogLogAttrsNonePollute, benchRlogLogAttrsNonePollute}, + {"Info-kv+pollute", benchSlogInfoKVPollute, benchRlogInfoKVPollute}, + {"Log-kv+pollute", benchSlogLogKVPollute, benchRlogLogKVPollute}, + } + + t.Log("rlog vs slog — isolated runs (positive % = rlog slower; negative = rlog faster)") + var sumPct float64 + for _, p := range pairs { + sNs, rNs := nsPerOpOrderAvg(p.slogFn, p.rlogFn) + pct := pctRlogVsSlog(sNs, rNs) + sumPct += pct + dir := "slower" + if pct < 0 { + dir = "faster" + } + t.Logf("%s: slog %s/op rlog %s/op → rlog is %.1f%% %s than slog (order-averaged SR+RS)", + p.name, + formatNs(sNs), + formatNs(rNs), + math.Abs(pct), + dir, + ) + } + avg := sumPct / float64(len(pairs)) + t.Logf("mean signed difference (rlog vs slog): %+.1f%%", avg) + + t.Log("same pairs with cache pollution each iteration (order-averaged SR+RS)") + var sumPctP float64 + for _, p := range pairsPollute { + sNs, rNs := nsPerOpOrderAvg(p.slogFn, p.rlogFn) + pct := pctRlogVsSlog(sNs, rNs) + sumPctP += pct + dir := "slower" + if pct < 0 { + dir = "faster" + } + t.Logf("%s: slog %s/op rlog %s/op → rlog is %.1f%% %s than slog", + p.name, + formatNs(sNs), + formatNs(rNs), + math.Abs(pct), + dir, + ) + } + t.Logf("mean signed difference (+pollute): %+.1f%%", sumPctP/float64(len(pairsPollute))) + + // Baselines: single-purpose benchmarks (no slog/rlog pair). Help interpret how much of the + // full log path is Callers vs Trace-only vs a minimal Handle with PC=0. + t.Log("baselines (not compared to slog):") + for _, c := range []struct { + name string + fn func(*testing.B) + }{ + {"rlog/Trace-none", benchRlogTraceNone}, + {"runtime.Callers/skip2", benchRuntimeCallersSkip2}, + {"runtime.Callers/skip3", benchRuntimeCallersSkip3}, + {"directHandle-pc0", benchDirectHandlePC0}, + } { + res := testing.Benchmark(c.fn) + t.Logf(" %s: %s/op", c.name, formatNs(nsPerOp(res))) + } +} + +//============================================================================== +// Helpers (nop handler, benchmark bodies, small utilities) +//============================================================================== +// +// # Cache pollution (benchScratch + benchPolluteCache) +// +// Microbenchmarks that only call logging in a tight loop keep the logger’s code and small stack +// data in fast CPU caches (L1/L2) and train the branch predictor. That can hide real costs and +// make two similar paths look arbitrarily close—or make the second timed path look faster. +// +// benchPolluteCache is a deliberate “dirty the cache a bit” step: +// - benchScratch is 1 MiB (1<<20 bytes), larger than typical L1 and often larger than L2, so +// sequential or random touches can evict or replace lines that held logging code or stack. +// - We do not try to flush caches portably (no CLFLUSH, no privileged instructions); this is +// best-effort noise, not a hardware-level cache clear. +// - Each call performs 256 byte reads at indices spread with a prime stride (4093) and a per-iter +// mix (j). That scatters accesses across the buffer instead of hammering one cache line, which +// would be a different artifact. +// - The XOR accumulator is written to sink so the reads are not dead and the compiler keeps the loop. +// +// Limitations: other cores, prefetchers, and OS scheduling still dominate on some machines; results +// should be interpreted with [testing.B] variance and tools like benchstat, not as absolute truth. +// +// # Order averaging (nsPerOpOrderAvg) +// +// Four separate [testing.Benchmark] invocations per pair: SR (slog then rlog), RS (rlog then slog). +// Slog’s ns/op is (s1+s2)/2 and rlog’s is (r1+r2)/2 so each side is measured once as “first” and once +// as “second” after the competitor’s benchmark has run. + +// sink prevents the compiler from optimizing away benchmark bodies (Callers PC, pollution XOR). +var sink uintptr + +// benchScratch is the backing store for cache pollution; see package comment and benchPolluteCache. +var benchScratch []byte + +func init() { + // Non-zero contents so the buffer is not all zero pages with special OS behavior; also makes + // XOR depend on data the compiler cannot fold away. + benchScratch = make([]byte, 1<<20) + for i := range benchScratch { + benchScratch[i] = byte(i) + } +} + +// benchPolluteCache performs the read traffic described in the helpers section header. iter varies +// the starting phase so consecutive benchmark iterations do not hit the exact same addresses every time. +func benchPolluteCache(iter int) { + if len(benchScratch) == 0 { + return + } + // 256 loads, indices wrapped with &(len-1) because len is a power of two (cheap mask). + j := iter * 1103515245 // mix iteration index (linear congruential-style spread) + var s byte + for k := 0; k < 256; k++ { + s ^= benchScratch[(j+k*4093)&(len(benchScratch)-1)] + } + sink = uintptr(s) +} + +// nsPerOpOrderAvg returns averaged ns/op for slogFn and rlogFn after running SR then RS sequences. +func nsPerOpOrderAvg(slogFn, rlogFn func(*testing.B)) (slogNs, rlogNs float64) { + s1 := nsPerOp(testing.Benchmark(slogFn)) + r1 := nsPerOp(testing.Benchmark(rlogFn)) + r2 := nsPerOp(testing.Benchmark(rlogFn)) + s2 := nsPerOp(testing.Benchmark(slogFn)) + return (s1 + s2) / 2, (r1 + r2) / 2 +} + +// nopHandler is a slog.Handler that accepts every record and does nothing in Handle. All logging +// cost stays in the Logger wrapper and record construction—ideal for comparing rlog vs slog shape. +type nopHandler struct{} + +func (nopHandler) Enabled(context.Context, slog.Level) bool { return true } + +func (nopHandler) Handle(context.Context, slog.Record) error { return nil } + +func (nopHandler) WithAttrs([]slog.Attr) slog.Handler { return nopHandler{} } + +func (nopHandler) WithGroup(string) slog.Handler { return nopHandler{} } + +// benchEnv builds a fresh context and two loggers sharing the same nop handler: a raw *slog.Logger +// and an *rlog.Logger wrapping slog.New(same handler). Call once per benchmark function, not per b.N. +func benchEnv() (ctx context.Context, slogL *slog.Logger, rlogL *rlog.Logger, h nopHandler) { + ctx = context.Background() + h = nopHandler{} + slogL = slog.New(h) + rlogL = rlog.New(slog.New(h)) + return ctx, slogL, rlogL, h +} + +// --- Plain pairs (no pollution): tight loop, one log API call per iteration. --- + +func benchSlogLogAttrsNone(b *testing.B) { + ctx, slogL, _, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + slogL.LogAttrs(ctx, slog.LevelInfo, "msg") + } +} + +func benchRlogLogAttrsNone(b *testing.B) { + ctx, _, rlogL, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + rlogL.LogAttrs(ctx, slog.LevelInfo, "msg") + } +} + +func benchSlogInfoKV(b *testing.B) { + _, slogL, _, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + slogL.Info("msg", "a", 1) + } +} + +func benchRlogInfoKV(b *testing.B) { + _, _, rlogL, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + rlogL.Info("msg", "a", 1) + } +} + +func benchSlogLogKV(b *testing.B) { + ctx, slogL, _, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + slogL.Log(ctx, slog.LevelInfo, "msg", "a", 1) + } +} + +func benchRlogLogKV(b *testing.B) { + ctx, _, rlogL, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + rlogL.Log(ctx, slog.LevelInfo, "msg", "a", 1) + } +} + +// --- Polluted pairs: benchPolluteCache(i) runs immediately before each log call (same i as loop). --- + +func benchSlogLogAttrsNonePollute(b *testing.B) { + ctx, slogL, _, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + benchPolluteCache(i) + slogL.LogAttrs(ctx, slog.LevelInfo, "msg") + } +} + +func benchRlogLogAttrsNonePollute(b *testing.B) { + ctx, _, rlogL, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + benchPolluteCache(i) + rlogL.LogAttrs(ctx, slog.LevelInfo, "msg") + } +} + +func benchSlogInfoKVPollute(b *testing.B) { + _, slogL, _, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + benchPolluteCache(i) + slogL.Info("msg", "a", 1) + } +} + +func benchRlogInfoKVPollute(b *testing.B) { + _, _, rlogL, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + benchPolluteCache(i) + rlogL.Info("msg", "a", 1) + } +} + +func benchSlogLogKVPollute(b *testing.B) { + ctx, slogL, _, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + benchPolluteCache(i) + slogL.Log(ctx, slog.LevelInfo, "msg", "a", 1) + } +} + +func benchRlogLogKVPollute(b *testing.B) { + ctx, _, rlogL, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + benchPolluteCache(i) + rlogL.Log(ctx, slog.LevelInfo, "msg", "a", 1) + } +} + +// benchPairedInfoKVInterleaved runs slog.Info then rlog.Info every iteration, fixed order. +// Reported ns/op = total time / b.N, i.e. per pair of calls, not per single log. Useful to see both +// implementations in one loop (shared iteration overhead); the number is not directly comparable +// to the per-side sub-benchmarks without dividing by two and accounting for interaction effects. +func benchPairedInfoKVInterleaved(b *testing.B) { + _, slogL, rlogL, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + slogL.Info("msg", "a", 1) + rlogL.Info("msg", "a", 1) + } +} + +// --- rlog-only and PC baselines (no slog equivalent for Trace). --- + +func benchRlogTraceNone(b *testing.B) { + _, _, rlogL, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + rlogL.Trace("msg") + } +} + +// benchRuntimeCallersSkip2 measures a single Callers(2) per iteration (rlog-style skip depth). +func benchRuntimeCallersSkip2(b *testing.B) { + var pcs [1]uintptr + b.ReportAllocs() + for i := 0; i < b.N; i++ { + runtime.Callers(2, pcs[:]) + } + sink = pcs[0] +} + +// benchRuntimeCallersSkip3 measures a single Callers(3) per iteration (slog.Logger.log depth). +func benchRuntimeCallersSkip3(b *testing.B) { + var pcs [1]uintptr + b.ReportAllocs() + for i := 0; i < b.N; i++ { + runtime.Callers(3, pcs[:]) + } + sink = pcs[0] +} + +// benchDirectHandlePC0 bypasses Logger and Callers: builds a Record with PC==0 and invokes the nop +// handler. Approximates “if we did not capture source at all” plus minimal record + Handle overhead. +func benchDirectHandlePC0(b *testing.B) { + ctx, _, _, h := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + r := slog.NewRecord(time.Now(), slog.LevelInfo, "msg", 0) + _ = h.Handle(ctx, r) + } +} + +// nsPerOp converts [testing.BenchmarkResult] to nanoseconds per iteration. +func nsPerOp(r testing.BenchmarkResult) float64 { + if r.N == 0 { + return 0 + } + return float64(r.T.Nanoseconds()) / float64(r.N) +} + +// pctRlogVsSlog returns (rlog-slog)/slog * 100. Positive means rlog is slower than slog. +func pctRlogVsSlog(slogNs, rlogNs float64) float64 { + if slogNs == 0 { + return math.NaN() + } + return 100 * (rlogNs - slogNs) / slogNs +} + +// formatNs picks a readable precision for logging ns/op in test output. +func formatNs(ns float64) string { + if ns < 10 { + return fmt.Sprintf("%.2f ns", ns) + } + return fmt.Sprintf("%.1f ns", ns) +} diff --git a/rlog/rlog.go b/rlog/rlog.go index 865529a..36f3fbf 100644 --- a/rlog/rlog.go +++ b/rlog/rlog.go @@ -71,8 +71,10 @@ import ( "context" "log/slog" "os" + "runtime" "sync" "sync/atomic" + "time" ) //============================================================================= @@ -108,6 +110,34 @@ func (l *Logger) WithGroup(name string) *Logger { return &Logger{Logger: l.Logger.WithGroup(name)} } +// emit writes a record using a caller PC already captured at the public API +// boundary; behavior matches [slog.Logger]'s internal log path (nil ctx, Enabled, +// NewRecord, Handle). +func (l *Logger) emit(ctx context.Context, level slog.Level, msg string, pc uintptr, args ...any) { + if ctx == nil { + ctx = context.Background() + } + if !l.Enabled(ctx, level) { + return + } + r := slog.NewRecord(time.Now(), level, msg, pc) + r.Add(args...) + _ = l.Handler().Handle(ctx, r) +} + +// emitAttrs is like [Logger.emit] but for attribute-only records. +func (l *Logger) emitAttrs(ctx context.Context, level slog.Level, msg string, pc uintptr, attrs ...slog.Attr) { + if ctx == nil { + ctx = context.Background() + } + if !l.Enabled(ctx, level) { + return + } + r := slog.NewRecord(time.Now(), level, msg, pc) + r.AddAttrs(attrs...) + _ = l.Handler().Handle(ctx, r) +} + //============================================================================= // Global Logger Init and Management //============================================================================= @@ -187,263 +217,411 @@ func exitFatal() { } //============================================================================= -// Global Logger Functions -// NOTE: These functions are aliases for the [Logger] methods with the default [Logger]. +// Logger logging methods //============================================================================= -// With returns a derived [Logger] with the given attributes. -func With(args ...any) *Logger { - return Default().With(args...) +// Log emits a log record with the given level and message. Arguments are handled like +// [slog.Logger.Log]. +func (l *Logger) Log(ctx context.Context, level slog.Level, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(ctx, level, msg, pcs[0], args...) } -// WithGroup returns a derived [Logger] with the given group. -func WithGroup(name string) *Logger { - return Default().WithGroup(name) +// LogAttrs is like [Logger.Log] but accepts attrs only; attribute handling matches +// [slog.Logger.LogAttrs]. +func (l *Logger) LogAttrs(ctx context.Context, level slog.Level, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emitAttrs(ctx, level, msg, pcs[0], attrs...) } -// Log emits a log record with the given level and message using the [Default] logger. -// Arguments are handled like [slog.Logger.Log]. -func Log(ctx context.Context, level slog.Level, msg string, args ...any) { - Default().Log(ctx, level, msg, args...) +// Trace logs at [LevelTrace]. Arguments are handled like [slog.Logger.Log]; you can pass any +// number of key/value pairs or [slog.Attr] objects. +func (l *Logger) Trace(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(context.Background(), LevelTrace, msg, pcs[0], args...) } -// LogAttrs is like [Log] but accepts attrs only; it uses [slog.LogAttrs] for efficiency. -func LogAttrs(ctx context.Context, level slog.Level, msg string, attrs ...slog.Attr) { - Default().LogAttrs(ctx, level, msg, attrs...) +// TraceAttrs logs at [LevelTrace] with ctx and attrs. Attribute handling matches +// [slog.Logger.LogAttrs]. +func (l *Logger) TraceAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emitAttrs(ctx, LevelTrace, msg, pcs[0], attrs...) } -// Trace logs at [LevelTrace] using the [Default] logger. Arguments are handled like -// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. -func Trace(msg string, args ...any) { - Default().Trace(msg, args...) +// TraceContext logs at [LevelTrace] with ctx. Arguments are handled like [slog.Logger.Log]; you +// can pass any number of key/value pairs or [slog.Attr] objects. +func (l *Logger) TraceContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(ctx, LevelTrace, msg, pcs[0], args...) } -// Debug logs at [slog.LevelDebug] using the [Default] logger. Arguments are handled like -// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. -func Debug(msg string, args ...any) { - Default().Debug(msg, args...) +// Debug logs at [slog.LevelDebug]. Arguments are handled like [slog.Logger.Log]; you can pass +// any number of key/value pairs or [slog.Attr] objects. +func (l *Logger) Debug(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(context.Background(), slog.LevelDebug, msg, pcs[0], args...) } -// Info logs at [slog.LevelInfo] using the [Default] logger. Arguments are handled like -// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. -func Info(msg string, args ...any) { - Default().Info(msg, args...) +// DebugAttrs logs at [slog.LevelDebug] with ctx and attrs. Attribute handling matches +// [slog.Logger.LogAttrs]. +func (l *Logger) DebugAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emitAttrs(ctx, slog.LevelDebug, msg, pcs[0], attrs...) } -// Warn logs at [slog.LevelWarn] using the [Default] logger. Arguments are handled like -// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. -func Warn(msg string, args ...any) { - Default().Warn(msg, args...) +// DebugContext logs at [slog.LevelDebug] with ctx. Arguments are handled like [slog.Logger.Log]; +// you can pass any number of key/value pairs or [slog.Attr] objects. +func (l *Logger) DebugContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(ctx, slog.LevelDebug, msg, pcs[0], args...) } -// Error logs at [slog.LevelError] using the [Default] logger. Arguments are handled like -// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. -func Error(msg string, args ...any) { - Default().Error(msg, args...) +// Info logs at [slog.LevelInfo]. Arguments are handled like [slog.Logger.Log]; you can pass any +// number of key/value pairs or [slog.Attr] objects. +func (l *Logger) Info(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(context.Background(), slog.LevelInfo, msg, pcs[0], args...) } -// Fatal logs at [LevelFatal] using the [Default] logger, then runs the global fatal hook -// from [SetFatalHook] if set, otherwise [os.Exit](1). It does not return. Arguments are -// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. -func Fatal(msg string, args ...any) { - Default().Fatal(msg, args...) +// InfoAttrs logs at [slog.LevelInfo] with ctx and attrs. Attribute handling matches +// [slog.Logger.LogAttrs]. +func (l *Logger) InfoAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emitAttrs(ctx, slog.LevelInfo, msg, pcs[0], attrs...) } -// Panic logs at [LevelPanic] using the [Default] logger, then panics with msg. Arguments are -// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] -// objects. -func Panic(msg string, args ...any) { - Default().Panic(msg, args...) +// InfoContext logs at [slog.LevelInfo] with ctx. Arguments are handled like [slog.Logger.Log]; +// you can pass any number of key/value pairs or [slog.Attr] objects. +func (l *Logger) InfoContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(ctx, slog.LevelInfo, msg, pcs[0], args...) } -// TraceContext logs at [LevelTrace] with ctx using the [Default] logger. Arguments are handled -// like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. -func TraceContext(ctx context.Context, msg string, args ...any) { - Default().TraceContext(ctx, msg, args...) +// Warn logs at [slog.LevelWarn]. Arguments are handled like [slog.Logger.Log]; you can pass any +// number of key/value pairs or [slog.Attr] objects. +func (l *Logger) Warn(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(context.Background(), slog.LevelWarn, msg, pcs[0], args...) } -// DebugContext logs at [slog.LevelDebug] with ctx using the [Default] logger. Arguments are -// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] -// objects. -func DebugContext(ctx context.Context, msg string, args ...any) { - Default().DebugContext(ctx, msg, args...) +// WarnAttrs logs at [slog.LevelWarn] with ctx and attrs. Attribute handling matches +// [slog.Logger.LogAttrs]. +func (l *Logger) WarnAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emitAttrs(ctx, slog.LevelWarn, msg, pcs[0], attrs...) } -// InfoContext logs at [slog.LevelInfo] with ctx using the [Default] logger. Arguments are -// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] -// objects. -func InfoContext(ctx context.Context, msg string, args ...any) { - Default().InfoContext(ctx, msg, args...) +// WarnContext logs at [slog.LevelWarn] with ctx. Arguments are handled like [slog.Logger.Log]; +// you can pass any number of key/value pairs or [slog.Attr] objects. +func (l *Logger) WarnContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(ctx, slog.LevelWarn, msg, pcs[0], args...) } -// WarnContext logs at [slog.LevelWarn] with ctx using the [Default] logger. Arguments are -// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] -// objects. -func WarnContext(ctx context.Context, msg string, args ...any) { - Default().WarnContext(ctx, msg, args...) +// Error logs at [slog.LevelError]. Arguments are handled like [slog.Logger.Log]; you can pass any +// number of key/value pairs or [slog.Attr] objects. +func (l *Logger) Error(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(context.Background(), slog.LevelError, msg, pcs[0], args...) } -// ErrorContext logs at [slog.LevelError] with ctx using the [Default] logger. Arguments are -// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] -// objects. -func ErrorContext(ctx context.Context, msg string, args ...any) { - Default().ErrorContext(ctx, msg, args...) +// ErrorAttrs logs at [slog.LevelError] with ctx and attrs. Attribute handling matches +// [slog.Logger.LogAttrs]. +func (l *Logger) ErrorAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emitAttrs(ctx, slog.LevelError, msg, pcs[0], attrs...) } -// FatalContext logs at [LevelFatal] with ctx using the [Default] logger, then runs the global -// fatal hook from [SetFatalHook] if set, otherwise [os.Exit](1). It does not return. Arguments -// are handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. -func FatalContext(ctx context.Context, msg string, args ...any) { - Default().FatalContext(ctx, msg, args...) +// ErrorContext logs at [slog.LevelError] with ctx. Arguments are handled like [slog.Logger.Log]; +// you can pass any number of key/value pairs or [slog.Attr] objects. +func (l *Logger) ErrorContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(ctx, slog.LevelError, msg, pcs[0], args...) } -// PanicContext logs at [LevelPanic] with ctx using the [Default] logger, then panics with msg. -// Arguments are handled like [slog.Logger.Log]; you can pass any number of key/value pairs or -// [slog.Attr] objects. -func PanicContext(ctx context.Context, msg string, args ...any) { - Default().PanicContext(ctx, msg, args...) +// Fatal logs at [LevelFatal], then runs the global fatal hook from [SetFatalHook] if set, +// otherwise [os.Exit](1). It does not return. Arguments are handled like [slog.Logger.Log]; you +// can pass any number of key/value pairs or [slog.Attr] objects. +func (l *Logger) Fatal(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(context.Background(), LevelFatal, msg, pcs[0], args...) + exitFatal() } -// TraceAttrs logs at [LevelTrace] with ctx and attrs using the [Default] logger. Uses -// [slog.LogAttrs] for efficiency. -func TraceAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - Default().TraceAttrs(ctx, msg, attrs...) +// FatalAttrs logs at [LevelFatal] with ctx and attrs, then runs the global fatal hook from +// [SetFatalHook] if set, otherwise [os.Exit](1). It does not return. Attribute handling matches +// [slog.Logger.LogAttrs]. +func (l *Logger) FatalAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emitAttrs(ctx, LevelFatal, msg, pcs[0], attrs...) + exitFatal() } -// DebugAttrs logs at [slog.LevelDebug] with ctx and attrs using the [Default] logger. Uses -// [slog.LogAttrs] for efficiency. -func DebugAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - Default().DebugAttrs(ctx, msg, attrs...) +// FatalContext logs at [LevelFatal] with ctx, then runs the global fatal hook from [SetFatalHook] +// if set, otherwise [os.Exit](1). It does not return. Arguments are handled like +// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. +func (l *Logger) FatalContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(ctx, LevelFatal, msg, pcs[0], args...) + exitFatal() } -// InfoAttrs logs at [slog.LevelInfo] with ctx and attrs using the [Default] logger. Uses -// [slog.LogAttrs] for efficiency. -func InfoAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - Default().InfoAttrs(ctx, msg, attrs...) +// Panic logs at [LevelPanic], then panics with msg. Arguments are handled like [slog.Logger.Log]; +// you can pass any number of key/value pairs or [slog.Attr] objects. +func (l *Logger) Panic(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(context.Background(), LevelPanic, msg, pcs[0], args...) + panic(msg) } -// WarnAttrs logs at [slog.LevelWarn] with ctx and attrs using the [Default] logger. Uses -// [slog.LogAttrs] for efficiency. -func WarnAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - Default().WarnAttrs(ctx, msg, attrs...) +// PanicAttrs logs at [LevelPanic] with ctx and attrs, then panics with msg. Attribute handling +// matches [slog.Logger.LogAttrs]. +func (l *Logger) PanicAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emitAttrs(ctx, LevelPanic, msg, pcs[0], attrs...) + panic(msg) } -// ErrorAttrs logs at [slog.LevelError] with ctx and attrs using the [Default] logger. Uses -// [slog.LogAttrs] for efficiency. -func ErrorAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - Default().ErrorAttrs(ctx, msg, attrs...) +// PanicContext logs at [LevelPanic] with ctx, then panics with msg. Arguments are handled like +// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. +func (l *Logger) PanicContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(ctx, LevelPanic, msg, pcs[0], args...) + panic(msg) } -// FatalAttrs logs at [LevelFatal] with attrs using the [Default] logger, then runs the global -// fatal hook from [SetFatalHook] if set, otherwise [os.Exit](1). It does not return. Uses -// [slog.LogAttrs] for efficiency. -func FatalAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - Default().FatalAttrs(ctx, msg, attrs...) +//============================================================================= +// Global Logger Functions +// NOTE: These functions are aliases for the [Logger] methods with the [Default] [Logger]. +//============================================================================= + +// With returns a derived [Logger] with the given attributes. +func With(args ...any) *Logger { + return Default().With(args...) } -// PanicAttrs logs at [LevelPanic] with attrs using the [Default] logger, then panics with msg. -// Uses [slog.LogAttrs] for efficiency. -func PanicAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - Default().PanicAttrs(ctx, msg, attrs...) +// WithGroup returns a derived [Logger] with the given group. +func WithGroup(name string) *Logger { + return Default().WithGroup(name) } -//============================================================================= -// Attrs Functions for default slog levels -//============================================================================= +// Log emits a log record with the given level and message using the [Default] logger. +// Arguments are handled like [slog.Logger.Log]. +func Log(ctx context.Context, level slog.Level, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(ctx, level, msg, pcs[0], args...) +} -// DebugAttrs logs at slog.LevelDebug with ctx and attrs. Uses slog.LogAttrs for efficiency. -func (l *Logger) DebugAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - l.Logger.LogAttrs(ctx, slog.LevelDebug, msg, attrs...) +// LogAttrs is like [Log] but accepts attrs only; it uses [slog.LogAttrs] for efficiency. +func LogAttrs(ctx context.Context, level slog.Level, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emitAttrs(ctx, level, msg, pcs[0], attrs...) } -// InfoAttrs logs at slog.LevelInfo with ctx and attrs. Uses slog.LogAttrs for efficiency. -func (l *Logger) InfoAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - l.Logger.LogAttrs(ctx, slog.LevelInfo, msg, attrs...) +// Trace logs at [LevelTrace] using the [Default] logger. Arguments are handled like +// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. +func Trace(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(context.Background(), LevelTrace, msg, pcs[0], args...) } -// WarnAttrs logs at slog.LevelWarn with ctx and attrs. Uses slog.LogAttrs for efficiency. -func (l *Logger) WarnAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - l.Logger.LogAttrs(ctx, slog.LevelWarn, msg, attrs...) +// TraceAttrs logs at [LevelTrace] with ctx and attrs using the [Default] logger. Uses +// [slog.LogAttrs] for efficiency. +func TraceAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emitAttrs(ctx, LevelTrace, msg, pcs[0], attrs...) } -// ErrorAttrs logs at slog.LevelError with ctx and attrs. Uses slog.LogAttrs for efficiency. -func (l *Logger) ErrorAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - l.Logger.LogAttrs(ctx, slog.LevelError, msg, attrs...) +// TraceContext logs at [LevelTrace] with ctx using the [Default] logger. Arguments are handled +// like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. +func TraceContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(ctx, LevelTrace, msg, pcs[0], args...) } -//============================================================================= -// Trace Functions -//============================================================================= +// Debug logs at [slog.LevelDebug] using the [Default] logger. Arguments are handled like +// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. +func Debug(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(context.Background(), slog.LevelDebug, msg, pcs[0], args...) +} -// Trace logs at [LevelTrace]. Arguments are handled like [slog.Logger.Log]; you -// can pass any number of key/value pairs or [slog.Attr] objects. -func (l *Logger) Trace(msg string, args ...any) { - l.TraceContext(context.Background(), msg, args...) +// DebugAttrs logs at [slog.LevelDebug] with ctx and attrs using the [Default] logger. Uses +// [slog.LogAttrs] for efficiency. +func DebugAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emitAttrs(ctx, slog.LevelDebug, msg, pcs[0], attrs...) } -// TraceContext logs at [LevelTrace] with ctx. Arguments are handled like -// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] +// DebugContext logs at [slog.LevelDebug] with ctx using the [Default] logger. Arguments are +// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] // objects. -func (l *Logger) TraceContext(ctx context.Context, msg string, args ...any) { - l.Logger.Log(ctx, LevelTrace, msg, args...) +func DebugContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(ctx, slog.LevelDebug, msg, pcs[0], args...) } -// TraceAttrs logs at [LevelTrace] with ctx and attrs. Uses [slog.LogAttrs] for -// efficiency. -func (l *Logger) TraceAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - l.Logger.LogAttrs(ctx, LevelTrace, msg, attrs...) +// Info logs at [slog.LevelInfo] using the [Default] logger. Arguments are handled like +// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. +func Info(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(context.Background(), slog.LevelInfo, msg, pcs[0], args...) } -//============================================================================= -// Fatal Functions -//============================================================================= +// InfoAttrs logs at [slog.LevelInfo] with ctx and attrs using the [Default] logger. Uses +// [slog.LogAttrs] for efficiency. +func InfoAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emitAttrs(ctx, slog.LevelInfo, msg, pcs[0], attrs...) +} -// Fatal logs at [LevelFatal] then runs the global fatal hook from [SetFatalHook] if set, -// otherwise [os.Exit](1). It does not return. Arguments are handled like [slog.Logger.Log]; -// you can pass any number of key/value pairs or [slog.Attr] objects. -func (l *Logger) Fatal(msg string, args ...any) { - l.FatalContext(context.Background(), msg, args...) +// InfoContext logs at [slog.LevelInfo] with ctx using the [Default] logger. Arguments are +// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] +// objects. +func InfoContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(ctx, slog.LevelInfo, msg, pcs[0], args...) } -// FatalContext logs at [LevelFatal] with ctx then runs the global fatal hook from [SetFatalHook] -// if set, otherwise [os.Exit](1). It does not return. Arguments are handled like -// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] +// Warn logs at [slog.LevelWarn] using the [Default] logger. Arguments are handled like +// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. +func Warn(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(context.Background(), slog.LevelWarn, msg, pcs[0], args...) +} + +// WarnAttrs logs at [slog.LevelWarn] with ctx and attrs using the [Default] logger. Uses +// [slog.LogAttrs] for efficiency. +func WarnAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emitAttrs(ctx, slog.LevelWarn, msg, pcs[0], attrs...) +} + +// WarnContext logs at [slog.LevelWarn] with ctx using the [Default] logger. Arguments are +// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] // objects. -func (l *Logger) FatalContext(ctx context.Context, msg string, args ...any) { - l.Logger.Log(ctx, LevelFatal, msg, args...) +func WarnContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(ctx, slog.LevelWarn, msg, pcs[0], args...) +} + +// Error logs at [slog.LevelError] using the [Default] logger. Arguments are handled like +// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. +func Error(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(context.Background(), slog.LevelError, msg, pcs[0], args...) +} + +// ErrorAttrs logs at [slog.LevelError] with ctx and attrs using the [Default] logger. Uses +// [slog.LogAttrs] for efficiency. +func ErrorAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emitAttrs(ctx, slog.LevelError, msg, pcs[0], attrs...) +} + +// ErrorContext logs at [slog.LevelError] with ctx using the [Default] logger. Arguments are +// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] +// objects. +func ErrorContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(ctx, slog.LevelError, msg, pcs[0], args...) +} + +// Fatal logs at [LevelFatal] using the [Default] logger, then runs the global fatal hook +// from [SetFatalHook] if set, otherwise [os.Exit](1). It does not return. Arguments are +// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. +func Fatal(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(context.Background(), LevelFatal, msg, pcs[0], args...) exitFatal() } -// FatalAttrs logs at [LevelFatal] with attrs then runs the global fatal hook from [SetFatalHook] -// if set, otherwise [os.Exit](1). It does not return. Uses [slog.LogAttrs] for -// efficiency. -func (l *Logger) FatalAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - l.Logger.LogAttrs(ctx, LevelFatal, msg, attrs...) +// FatalAttrs logs at [LevelFatal] with attrs using the [Default] logger, then runs the global +// fatal hook from [SetFatalHook] if set, otherwise [os.Exit](1). It does not return. Uses +// [slog.LogAttrs] for efficiency. +func FatalAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emitAttrs(ctx, LevelFatal, msg, pcs[0], attrs...) exitFatal() } -//============================================================================= -// Panic Functions -//============================================================================= +// FatalContext logs at [LevelFatal] with ctx using the [Default] logger, then runs the global +// fatal hook from [SetFatalHook] if set, otherwise [os.Exit](1). It does not return. Arguments +// are handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. +func FatalContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(ctx, LevelFatal, msg, pcs[0], args...) + exitFatal() +} -// Panic logs at [LevelPanic] then panics with msg. Arguments are handled like -// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] +// Panic logs at [LevelPanic] using the [Default] logger, then panics with msg. Arguments are +// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] // objects. -func (l *Logger) Panic(msg string, args ...any) { - l.PanicContext(context.Background(), msg, args...) +func Panic(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(context.Background(), LevelPanic, msg, pcs[0], args...) + panic(msg) } -// PanicContext logs at [LevelPanic] with ctx then panics with msg. Arguments -// are handled like [slog.Logger.Log]; you can pass any number of key/value -// pairs or [slog.Attr] objects. -func (l *Logger) PanicContext(ctx context.Context, msg string, args ...any) { - l.Logger.Log(ctx, LevelPanic, msg, args...) +// PanicAttrs logs at [LevelPanic] with attrs using the [Default] logger, then panics with msg. +// Uses [slog.LogAttrs] for efficiency. +func PanicAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emitAttrs(ctx, LevelPanic, msg, pcs[0], attrs...) panic(msg) } -// PanicAttrs logs at [LevelPanic] with attrs then panics with msg. Uses -// [slog.LogAttrs] for efficiency. -func (l *Logger) PanicAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - l.Logger.LogAttrs(ctx, LevelPanic, msg, attrs...) +// PanicContext logs at [LevelPanic] with ctx using the [Default] logger, then panics with msg. +// Arguments are handled like [slog.Logger.Log]; you can pass any number of key/value pairs or +// [slog.Attr] objects. +func PanicContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(ctx, LevelPanic, msg, pcs[0], args...) panic(msg) } diff --git a/rlog/rlog_test.go b/rlog/rlog_test.go index 452282a..724c9bd 100644 --- a/rlog/rlog_test.go +++ b/rlog/rlog_test.go @@ -3,8 +3,10 @@ package rlog_test import ( "bytes" "context" + "encoding/json" "io" "log/slog" + "path/filepath" "sync" "sync/atomic" "testing" @@ -175,6 +177,53 @@ func TestPanic(t *testing.T) { }) } +// AddSource should attribute the call site in test code, not rlog.go (wrapper frames). +func TestAddSourceSkipsRlogWrapper(t *testing.T) { + type sourceRow struct { + Source struct { + File string `json:"file"` + } `json:"source"` + } + + var buf bytes.Buffer + opts := &slog.HandlerOptions{Level: rlog.LevelTrace, AddSource: true} + log := newTestLogger(t, &buf, opts) + + prev := rlog.Default() + t.Cleanup(func() { rlog.SetDefault(prev) }) + rlog.SetDefault(log) + + t.Run("Logger.Trace", func(t *testing.T) { + buf.Reset() + log.Trace("m") + var r sourceRow + assert.Ok(t, json.Unmarshal(buf.Bytes(), &r)) + base := filepath.Base(r.Source.File) + assert.NotEqual(t, "rlog.go", base, "source must not be rlog implementation file") + assert.Equal(t, "rlog_test.go", base) + }) + + t.Run("Logger.Info", func(t *testing.T) { + buf.Reset() + log.Info("m") + var r sourceRow + assert.Ok(t, json.Unmarshal(buf.Bytes(), &r)) + base := filepath.Base(r.Source.File) + assert.NotEqual(t, "rlog.go", base) + assert.Equal(t, "rlog_test.go", base) + }) + + t.Run("package_Info", func(t *testing.T) { + buf.Reset() + rlog.Info("m") + var r sourceRow + assert.Ok(t, json.Unmarshal(buf.Bytes(), &r)) + base := filepath.Base(r.Source.File) + assert.NotEqual(t, "rlog.go", base) + assert.Equal(t, "rlog_test.go", base) + }) +} + // Concurrent SetDefault, Default, and package-level logging (run with -race). func TestDefaultSetDefault_concurrent(t *testing.T) { // Pool of loggers to rotate under SetDefault. From 3273cd8505f4ba431ebb6e3ea5df54f15b926b30 Mon Sep 17 00:00:00 2001 From: Chris Okuda Date: Sat, 28 Mar 2026 21:06:16 -1000 Subject: [PATCH 16/18] rename it back to make the diff better in github :( --- rlog/{rlog.go => logger.go} | 0 rlog/{rlog_test.go => logger_test.go} | 0 2 files changed, 0 insertions(+), 0 deletions(-) rename rlog/{rlog.go => logger.go} (100%) rename rlog/{rlog_test.go => logger_test.go} (100%) diff --git a/rlog/rlog.go b/rlog/logger.go similarity index 100% rename from rlog/rlog.go rename to rlog/logger.go diff --git a/rlog/rlog_test.go b/rlog/logger_test.go similarity index 100% rename from rlog/rlog_test.go rename to rlog/logger_test.go From dc8358e1602f2e6f01ac49e0c9966b4ddf4cca86 Mon Sep 17 00:00:00 2001 From: Chris Okuda Date: Sat, 28 Mar 2026 21:16:42 -1000 Subject: [PATCH 17/18] skip if short and fix test --- rlog/benchmark_test.go | 4 ++++ rlog/logger_test.go | 6 +++--- 2 files changed, 7 insertions(+), 3 deletions(-) diff --git a/rlog/benchmark_test.go b/rlog/benchmark_test.go index 2390393..e8c441f 100644 --- a/rlog/benchmark_test.go +++ b/rlog/benchmark_test.go @@ -52,6 +52,10 @@ import ( // // rlog cannot use [log/slog/internal.IgnorePC] (stdlib-only); slog’s -nopc benchmark flag does not apply here. func BenchmarkLoggerVsSlog(b *testing.B) { + if testing.Short() { + b.Skip("skip bench in -short") + } + b.Run("slog/LogAttrs-none", benchSlogLogAttrsNone) b.Run("rlog/LogAttrs-none", benchRlogLogAttrsNone) b.Run("slog/Info-kv", benchSlogInfoKV) diff --git a/rlog/logger_test.go b/rlog/logger_test.go index 724c9bd..36a25ad 100644 --- a/rlog/logger_test.go +++ b/rlog/logger_test.go @@ -200,7 +200,7 @@ func TestAddSourceSkipsRlogWrapper(t *testing.T) { assert.Ok(t, json.Unmarshal(buf.Bytes(), &r)) base := filepath.Base(r.Source.File) assert.NotEqual(t, "rlog.go", base, "source must not be rlog implementation file") - assert.Equal(t, "rlog_test.go", base) + assert.Equal(t, "logger_test.go", base) }) t.Run("Logger.Info", func(t *testing.T) { @@ -210,7 +210,7 @@ func TestAddSourceSkipsRlogWrapper(t *testing.T) { assert.Ok(t, json.Unmarshal(buf.Bytes(), &r)) base := filepath.Base(r.Source.File) assert.NotEqual(t, "rlog.go", base) - assert.Equal(t, "rlog_test.go", base) + assert.Equal(t, "logger_test.go", base) }) t.Run("package_Info", func(t *testing.T) { @@ -220,7 +220,7 @@ func TestAddSourceSkipsRlogWrapper(t *testing.T) { assert.Ok(t, json.Unmarshal(buf.Bytes(), &r)) base := filepath.Base(r.Source.File) assert.NotEqual(t, "rlog.go", base) - assert.Equal(t, "rlog_test.go", base) + assert.Equal(t, "logger_test.go", base) }) } From 1e2c7320a70508e2c57afe7da6b8745b7184369a Mon Sep 17 00:00:00 2001 From: Chris Okuda Date: Sat, 28 Mar 2026 21:27:52 -1000 Subject: [PATCH 18/18] don't run the benchmark comparison test without an env var which won't be set except when the user sets it --- rlog/benchmark_test.go | 20 +++++++++++++------- 1 file changed, 13 insertions(+), 7 deletions(-) diff --git a/rlog/benchmark_test.go b/rlog/benchmark_test.go index e8c441f..40b0ee6 100644 --- a/rlog/benchmark_test.go +++ b/rlog/benchmark_test.go @@ -5,6 +5,7 @@ import ( "fmt" "log/slog" "math" + "os" "runtime" "testing" "time" @@ -12,6 +13,11 @@ import ( "go.rtnl.ai/x/rlog" ) +// envRunLoggerVsSlogCompare must be set to "1" to run [TestLoggerVsSlogCompare]. That keeps plain +// go test and IDE "run test" (which pass -run by name) from executing this slow comparison unless +// you opt in from a real shell. +const envRunLoggerVsSlogCompare = "RLOG_LOGGER_VS_SLOG_COMPARE" + // BenchmarkLoggerVsSlog compares *rlog.Logger with *slog.Logger on identical nop handlers. // // # What every logging sub-benchmark measures @@ -48,14 +54,10 @@ import ( // // Percentage summary (slower/faster), with order averaging and a polluted section: // -// go test ./rlog -run TestLoggerVsSlogCompare -v +// RLOG_LOGGER_VS_SLOG_COMPARE=1 go test ./rlog -run TestLoggerVsSlogCompare -v // // rlog cannot use [log/slog/internal.IgnorePC] (stdlib-only); slog’s -nopc benchmark flag does not apply here. func BenchmarkLoggerVsSlog(b *testing.B) { - if testing.Short() { - b.Skip("skip bench in -short") - } - b.Run("slog/LogAttrs-none", benchSlogLogAttrsNone) b.Run("rlog/LogAttrs-none", benchRlogLogAttrsNone) b.Run("slog/Info-kv", benchSlogInfoKV) @@ -97,10 +99,14 @@ func BenchmarkLoggerVsSlog(b *testing.B) { // The final lines log rlog-only and PC-only benchmarks so you can sanity-check Callers cost vs full log. // // Skipped under -short (this test runs many benchmarks and can take tens of seconds). -// Run: go test ./rlog -run TestLoggerVsSlogCompare -v +// Skipped unless [envRunLoggerVsSlogCompare] is set to "1" (avoids IDE "run test" and plain go test). +// Run: RLOG_LOGGER_VS_SLOG_COMPARE=1 go test ./rlog -run TestLoggerVsSlogCompare -v func TestLoggerVsSlogCompare(t *testing.T) { if testing.Short() { - t.Skip("skip bench comparison in -short") + t.Skip("skip bench comparison in short mode") + } + if os.Getenv(envRunLoggerVsSlogCompare) != "1" { + t.Skipf("set %s=1 to run this comparison (IDE and default go test skip)", envRunLoggerVsSlogCompare) } pairs := []struct {