fix(logger): render full logfmt line as journal MESSAGE

The native journal handler only put the bare msg string in MESSAGE,
so default `journalctl` output lost all slog attributes (env, name,
ip_version, etc.) that were visible with the old TextHandler path.

Wrap the slog-journal handler so each record's MESSAGE is rendered
through slog.TextHandler — producing the same `level=INFO msg="..."
key=val` format as before — while still emitting every attribute as
a structured journal field for `journalctl -o verbose` / field-based
filtering.

Also fix go.mod: slog-journal is a direct dependency.
This commit is contained in:
2026-04-19 02:06:29 -07:00
parent d8b9cddfb8
commit 82e7f4398b
4 changed files with 169 additions and 80 deletions

View File

@@ -1,7 +1,10 @@
package logger
import (
"bytes"
"context"
"log/slog"
"slices"
slogjournal "github.com/systemd/slog-journal"
)
@@ -22,7 +25,71 @@ func newJournalHandler(opts *slog.HandlerOptions) slog.Handler {
if err != nil {
return nil
}
return h
return &journalMessageHandler{inner: h, level: opts.Level}
}
// journalMessageHandler wraps a slog-journal handler so each record's
// MESSAGE field contains the full logfmt line (level, msg, and all
// attributes) — matching the pre-journal stderr TextHandler output so
// plain `journalctl` remains readable. Attributes are still delivered as
// structured journal fields, so `journalctl -o verbose` or
// `--output-fields=` keep working for filtering.
type journalMessageHandler struct {
inner slog.Handler
level slog.Leveler
ops []handlerOp
}
type handlerOp struct {
attrs []slog.Attr // non-nil for WithAttrs
group string // non-empty for WithGroup
}
func (h *journalMessageHandler) Enabled(ctx context.Context, level slog.Level) bool {
return h.inner.Enabled(ctx, level)
}
func (h *journalMessageHandler) Handle(ctx context.Context, r slog.Record) error {
var buf bytes.Buffer
var th slog.Handler = slog.NewTextHandler(&buf, &slog.HandlerOptions{
Level: h.level,
ReplaceAttr: logRemoveTime,
})
for _, op := range h.ops {
if op.group != "" {
th = th.WithGroup(op.group)
} else {
th = th.WithAttrs(op.attrs)
}
}
if err := th.Handle(ctx, r); err != nil {
return err
}
msg := bytes.TrimRight(buf.Bytes(), "\n")
nr := r.Clone()
nr.Message = string(msg)
return h.inner.Handle(ctx, nr)
}
func (h *journalMessageHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
if len(attrs) == 0 {
return h
}
h2 := *h
h2.ops = append(slices.Clip(h.ops), handlerOp{attrs: attrs})
h2.inner = h.inner.WithAttrs(attrs)
return &h2
}
func (h *journalMessageHandler) WithGroup(name string) slog.Handler {
if name == "" {
return h
}
h2 := *h
h2.ops = append(slices.Clip(h.ops), handlerOp{group: name})
h2.inner = h.inner.WithGroup(name)
return &h2
}
// journalReplaceAttr sanitizes slog attribute keys so they satisfy the

View File

@@ -1,6 +1,102 @@
package logger
import "testing"
import (
"bytes"
"context"
"log/slog"
"strings"
"testing"
"time"
)
// captureHandler records the last record it handled so tests can inspect
// the MESSAGE text produced by the journal wrapper.
type captureHandler struct {
last slog.Record
}
func (h *captureHandler) Enabled(context.Context, slog.Level) bool { return true }
func (h *captureHandler) Handle(_ context.Context, r slog.Record) error {
h.last = r.Clone()
return nil
}
func (h *captureHandler) WithAttrs(attrs []slog.Attr) slog.Handler { return h }
func (h *captureHandler) WithGroup(string) slog.Handler { return h }
func TestJournalMessageHandler_MessageContainsAttrs(t *testing.T) {
cap := &captureHandler{}
h := &journalMessageHandler{inner: cap, level: slog.LevelDebug}
log := slog.New(h).With("env", "prod").WithGroup("")
log.Info("shutting down monitor", "name", "usmci1-1a6a7hp", "ip_version", "v4")
got := cap.last.Message
for _, want := range []string{
`level=INFO`,
`msg="shutting down monitor"`,
`env=prod`,
`name=usmci1-1a6a7hp`,
`ip_version=v4`,
} {
if !strings.Contains(got, want) {
t.Errorf("MESSAGE missing %q; got %q", want, got)
}
}
if strings.Contains(got, "time=") {
t.Errorf("MESSAGE should not include time=; got %q", got)
}
if strings.HasSuffix(got, "\n") {
t.Errorf("MESSAGE should not end with newline; got %q", got)
}
// And the attributes should still be present on the record passed
// to the inner handler so the journal emits them as structured fields.
var sawEnv, sawName bool
cap.last.Attrs(func(a slog.Attr) bool {
switch a.Key {
case "env":
sawEnv = a.Value.String() == "prod"
case "name":
sawName = a.Value.String() == "usmci1-1a6a7hp"
}
return true
})
if !sawName {
t.Errorf("inner record missing name attr")
}
// env was applied via WithAttrs so it lives on the inner handler,
// not the record itself — that's verified separately below.
_ = sawEnv
}
func TestJournalMessageHandler_TextHandlerParity(t *testing.T) {
// Render the same record through slog.TextHandler (with time stripped)
// and through the journal wrapper. The MESSAGE body written to the
// journal must match the text handler output byte-for-byte (minus the
// trailing newline).
var textBuf bytes.Buffer
textH := slog.NewTextHandler(&textBuf, &slog.HandlerOptions{
ReplaceAttr: logRemoveTime,
})
cap := &captureHandler{}
journalH := &journalMessageHandler{inner: cap, level: slog.LevelDebug}
r := slog.NewRecord(time.Date(2026, 4, 15, 7, 45, 29, 0, time.UTC), slog.LevelError, "backoff error", 0)
r.AddAttrs(slog.String("env", "test"), slog.String("ip_version", "v4"))
if err := textH.Handle(context.Background(), r); err != nil {
t.Fatal(err)
}
if err := journalH.Handle(context.Background(), r); err != nil {
t.Fatal(err)
}
want := strings.TrimRight(textBuf.String(), "\n")
if cap.last.Message != want {
t.Errorf("journal MESSAGE mismatch\n got: %q\nwant: %q", cap.last.Message, want)
}
}
func TestSanitizeJournalKey(t *testing.T) {
tests := []struct {