From 050a712bbed9d2229a00ebec80fc3dbbf6cce073 Mon Sep 17 00:00:00 2001 From: Alec Thomas Date: Wed, 18 Feb 2026 10:44:38 +1100 Subject: [PATCH] refactor: include direct attributes in log message ``` logger.InfoContext("My message", "err", err, "id", id) -> {"message": "My message (err=..., id=...)", "err": "...", "id": ...} ``` This helps with log viewing systems like DataDog, where the message attributes can get lost in all the other inherited attributes --- internal/logging/logging.go | 2 +- internal/logging/messagehandler.go | 67 ++++++++++++++ internal/logging/messagehandler_test.go | 115 ++++++++++++++++++++++++ 3 files changed, 183 insertions(+), 1 deletion(-) create mode 100644 internal/logging/messagehandler.go create mode 100644 internal/logging/messagehandler_test.go diff --git a/internal/logging/logging.go b/internal/logging/logging.go index b043147..45a9bbd 100644 --- a/internal/logging/logging.go +++ b/internal/logging/logging.go @@ -32,7 +32,7 @@ func Configure(ctx context.Context, config Config) (*slog.Logger, context.Contex return a } } - handler = slog.NewJSONHandler(os.Stdout, options) + handler = &messageHandler{inner: slog.NewJSONHandler(os.Stdout, options)} } else { handler = tint.NewHandler(os.Stderr, &tint.Options{ Level: config.Level, diff --git a/internal/logging/messagehandler.go b/internal/logging/messagehandler.go new file mode 100644 index 0000000..7f89d1b --- /dev/null +++ b/internal/logging/messagehandler.go @@ -0,0 +1,67 @@ +package logging + +import ( + "context" + "fmt" + "log/slog" + "strings" + + "github.com/alecthomas/errors" +) + +// messageHandler wraps a slog.Handler and appends record attributes to the +// message text for easier debugging (e.g. "My message (err=..., id=...)"). +type messageHandler struct { + inner slog.Handler +} + +func (h *messageHandler) Enabled(ctx context.Context, level slog.Level) bool { + return h.inner.Enabled(ctx, level) +} + +func (h *messageHandler) Handle(ctx context.Context, r slog.Record) error { + if r.NumAttrs() > 0 { + var b strings.Builder + first := true + r.Attrs(func(a slog.Attr) bool { + if first { + first = false + } else { + b.WriteString(", ") + } + fmt.Fprintf(&b, "%s=%s", a.Key, formatValue(a.Value)) + return true + }) + r.Message = r.Message + " (" + b.String() + ")" + } + return errors.Wrap(h.inner.Handle(ctx, r), "handle log record") +} + +func needsQuoting(s string) bool { + for _, c := range s { + if c <= ' ' || c == '"' || c == ',' || c == '=' || c == '(' || c == ')' { + return true + } + } + return false +} + +func formatValue(v slog.Value) string { + v = v.Resolve() + if v.Kind() == slog.KindString { + s := v.String() + if s == "" || needsQuoting(s) { + return fmt.Sprintf("%q", s) + } + return s + } + return v.String() +} + +func (h *messageHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + return &messageHandler{inner: h.inner.WithAttrs(attrs)} +} + +func (h *messageHandler) WithGroup(name string) slog.Handler { + return &messageHandler{inner: h.inner.WithGroup(name)} +} diff --git a/internal/logging/messagehandler_test.go b/internal/logging/messagehandler_test.go new file mode 100644 index 0000000..ef94912 --- /dev/null +++ b/internal/logging/messagehandler_test.go @@ -0,0 +1,115 @@ +package logging //nolint:testpackage + +import ( + "bytes" + "context" + "encoding/json" + "log/slog" + "testing" + + "github.com/alecthomas/assert/v2" +) + +func TestMessageHandler(t *testing.T) { + type logEntry struct { + Level string `json:"level"` + Msg string `json:"msg"` + Err string `json:"err,omitempty"` + ID int `json:"id,omitempty"` + Request string `json:"request,omitempty"` + } + + tests := []struct { + name string + msg string + attrs []slog.Attr + wantMsg string + }{ + { + name: "NoAttrs", + msg: "simple message", + wantMsg: "simple message", + }, + { + name: "SingleAttr", + msg: "failed", + attrs: []slog.Attr{slog.String("err", "timeout")}, + wantMsg: "failed (err=timeout)", + }, + { + name: "MultipleAttrs", + msg: "request handled", + attrs: []slog.Attr{ + slog.String("request", "/foo"), + slog.Int("id", 42), + }, + wantMsg: "request handled (request=/foo, id=42)", + }, + { + name: "QuotedStringWithSpaces", + msg: "failed", + attrs: []slog.Attr{slog.String("err", "connection refused, try again")}, + wantMsg: `failed (err="connection refused, try again")`, + }, + { + name: "EmptyString", + msg: "failed", + attrs: []slog.Attr{slog.String("reason", "")}, + wantMsg: `failed (reason="")`, + }, + { + name: "SimpleWordUnquoted", + msg: "done", + attrs: []slog.Attr{slog.String("status", "ok")}, + wantMsg: "done (status=ok)", + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + var buf bytes.Buffer + inner := slog.NewJSONHandler(&buf, &slog.HandlerOptions{ + Level: slog.LevelDebug, + ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr { + if a.Key == slog.TimeKey { + return slog.Attr{} + } + return a + }, + }) + handler := &messageHandler{inner: inner} + logger := slog.New(handler) + + args := make([]any, 0, len(tt.attrs)*2) + for _, a := range tt.attrs { + args = append(args, a.Key, a.Value) + } + logger.Info(tt.msg, args...) + + var entry logEntry + assert.NoError(t, json.Unmarshal(buf.Bytes(), &entry)) + assert.Equal(t, tt.wantMsg, entry.Msg) + }) + } +} + +func TestMessageHandlerWithContextAttrs(t *testing.T) { + var buf bytes.Buffer + inner := slog.NewJSONHandler(&buf, &slog.HandlerOptions{ + ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr { + if a.Key == slog.TimeKey { + return slog.Attr{} + } + return a + }, + }) + handler := &messageHandler{inner: inner} + logger := slog.New(handler).With("client", "10.0.0.1") + logger.InfoContext(context.Background(), "connected", "id", 7) + + var entry map[string]any + assert.NoError(t, json.Unmarshal(buf.Bytes(), &entry)) + // Only record-level attrs appear in the message suffix; context attrs do not. + assert.Equal(t, "connected (id=7)", entry["msg"]) + assert.Equal(t, "10.0.0.1", entry["client"]) + assert.Equal(t, float64(7), entry["id"].(float64)) +}