pkg/logger: human handler UX— colon format- debug mode- dedup counter

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
This commit is contained in:
djmil 2026-06-03 18:48:51 +00:00
parent 4301f11efd
commit 5ec8e6999a
4 changed files with 341 additions and 71 deletions

View File

@ -55,8 +55,17 @@ func main() {
}
func (a *app) run() {
a.log.Debug("processing", "name", a.cfg.Greeter.Name)
defer a.log.Close()
// Warm up the greeter with a few names before the real call.
// In debug mode this produces repeated identical debug lines from the greeter,
// demonstrating how the deduplication counter collapses them in-place.
for _, name := range []string{"Alice", "Bob", "Carol", "Dave"} {
a.greeter.Greet(name)
}
a.showGreeting(a.cfg.Greeter.Name)
fmt.Printf("TODO: implement listening on port %d\n", a.cfg.App.Port)
}

View File

@ -18,55 +18,179 @@ func isTerminal(f *os.File) bool {
return err == nil && info.Mode()&os.ModeCharDevice != 0
}
// writeState holds shared mutable display state for a humanHandler family.
// Shared via pointer across parent and all derived handlers (WithAttrs, WithGroup)
// so that a child-logger INFO write correctly commits a parent-started debug line.
type writeState struct {
mu sync.Mutex
lastDebug string // original message text used for deduplication comparison
lastDisplay string // display form stored for counter rewrites (msg or msg+...)
debugN int // consecutive repeat count (0 = no pending debug line)
pendingNL bool // true when last write was a debug line without trailing newline
}
// humanHandler writes human-readable log lines to w with no timestamp.
//
// Format:
// Two operating modes, selected by handler level at construction:
//
// INFO: message key=val … (no prefix — the program's normal voice)
// WARN: warning: message key=val …
// ERROR: error: message key=val …
// DEBUG: debug: message key=val …
// Normal mode (level > DEBUG):
//
// INFO: message... "..." signals hidden structured fields (see debug file)
// INFO: message (no suffix when no fields)
// WARN: warning: msg: k=v, … always full fields — needs immediate visibility
// ERROR: error: msg: k=v, … always full fields — needs immediate visibility
//
// Debug mode (level <= DEBUG):
//
// DEBUG: debug: message... fields hidden; identical consecutive messages collapse:
// debug: message... ×N live counter updated in-place with \r
// INFO: message: k=v, … full fields — debug mode dumps everything
// WARN: warning: msg: k=v, …
// ERROR: error: msg: k=v, …
type humanHandler struct {
w io.Writer
level slog.Level
mu sync.Mutex
state *writeState // shared with all derived handlers
attrs []slog.Attr
prefix string // dot-separated group prefix for attribute keys
prefix string
}
func newHumanHandler(w io.Writer, level slog.Level) *humanHandler {
return &humanHandler{w: w, level: level}
return &humanHandler{w: w, level: level, state: &writeState{}}
}
func (h *humanHandler) debugMode() bool { return h.level <= slog.LevelDebug }
func (h *humanHandler) Enabled(_ context.Context, level slog.Level) bool {
return level >= h.level
}
func (h *humanHandler) Handle(_ context.Context, r slog.Record) error {
h.state.mu.Lock()
defer h.state.mu.Unlock()
switch {
case r.Level < slog.LevelInfo:
return h.handleDebug(r)
case r.Level < slog.LevelWarn:
return h.handleInfo(r)
default:
return h.handleImportant(r)
}
}
// handleDebug shows message + "..." if fields, with live deduplication counter.
// Fields are suppressed on screen even in debug mode — they change per iteration
// and would make the counter rewrite misleading; full values are in the debug file.
// Assumes state.mu is held.
func (h *humanHandler) handleDebug(r slog.Record) error {
display := h.ellipsis(r)
if r.Message == h.state.lastDebug {
h.state.debugN++
_, err := fmt.Fprintf(h.w, "\r%s ×%d", h.state.lastDisplay, h.state.debugN)
return err
}
if err := h.commitPending(); err != nil {
return err
}
h.state.lastDebug = r.Message
h.state.lastDisplay = display
h.state.debugN = 1
h.state.pendingNL = true
_, err := fmt.Fprintf(h.w, "%s", display)
return err
}
// handleInfo shows the full line in debug mode; hides fields with "..." in normal mode.
// Assumes state.mu is held.
func (h *humanHandler) handleInfo(r slog.Record) error {
if err := h.commitPending(); err != nil {
return err
}
var line string
if h.debugMode() {
line = h.fullLine(r)
} else {
line = h.ellipsis(r)
}
_, err := fmt.Fprintf(h.w, "%s\n", line)
return err
}
// handleImportant always shows the full line — WARN and ERROR need immediate full visibility.
// Assumes state.mu is held.
func (h *humanHandler) handleImportant(r slog.Record) error {
if err := h.commitPending(); err != nil {
return err
}
_, err := fmt.Fprintf(h.w, "%s\n", h.fullLine(r))
return err
}
func (h *humanHandler) commitPending() error {
if h.state.pendingNL {
h.state.pendingNL = false
h.state.lastDebug = ""
h.state.lastDisplay = ""
h.state.debugN = 0
_, err := io.WriteString(h.w, "\n")
return err
}
return nil
}
// fullLine builds "prefix message: k=v, k=v" with all structured fields.
func (h *humanHandler) fullLine(r slog.Record) string {
var b strings.Builder
b.WriteString(humanLevel(r.Level))
b.WriteString(r.Message)
var parts []string
for _, a := range h.attrs {
appendAttr(&b, h.prefix, a)
collectAttr(&parts, h.prefix, a)
}
r.Attrs(func(a slog.Attr) bool {
appendAttr(&b, h.prefix, a)
collectAttr(&parts, h.prefix, a)
return true
})
b.WriteByte('\n')
if len(parts) > 0 {
b.WriteString(": ")
b.WriteString(strings.Join(parts, ", "))
}
return b.String()
}
h.mu.Lock()
defer h.mu.Unlock()
_, err := io.WriteString(h.w, b.String())
return err
// ellipsis builds "prefix message" with "..." appended when structured fields exist.
func (h *humanHandler) ellipsis(r slog.Record) string {
hasFields := len(h.attrs) > 0
if !hasFields {
r.Attrs(func(_ slog.Attr) bool {
hasFields = true
return false
})
}
s := humanLevel(r.Level) + r.Message
if hasFields {
s += "..."
}
return s
}
// flush commits any pending debug line by writing the trailing newline.
// Called via Logger.Close() before process exit.
func (h *humanHandler) flush() {
h.state.mu.Lock()
defer h.state.mu.Unlock()
if h.state.pendingNL {
h.state.pendingNL = false
_, _ = io.WriteString(h.w, "\n")
}
}
func (h *humanHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
merged := make([]slog.Attr, len(h.attrs)+len(attrs))
copy(merged, h.attrs)
copy(merged[len(h.attrs):], attrs)
return &humanHandler{w: h.w, level: h.level, attrs: merged, prefix: h.prefix}
return &humanHandler{w: h.w, level: h.level, state: h.state, attrs: merged, prefix: h.prefix}
}
func (h *humanHandler) WithGroup(name string) slog.Handler {
@ -77,12 +201,11 @@ func (h *humanHandler) WithGroup(name string) slog.Handler {
if prefix != "" {
prefix += "."
}
return &humanHandler{w: h.w, level: h.level, attrs: h.attrs, prefix: prefix + name}
return &humanHandler{w: h.w, level: h.level, state: h.state, attrs: h.attrs, prefix: prefix + name}
}
// multiHandler fans a single log record out to multiple handlers.
// Each sub-handler's own Enabled filter is respected independently,
// so different handlers can capture different level ranges.
// Each sub-handler's own Enabled filter is respected independently.
type multiHandler []slog.Handler
func (m multiHandler) Enabled(ctx context.Context, level slog.Level) bool {
@ -122,6 +245,14 @@ func (m multiHandler) WithGroup(name string) slog.Handler {
return handlers
}
func (m multiHandler) flush() {
for _, h := range m {
if f, ok := h.(interface{ flush() error }); ok {
_ = f.flush()
}
}
}
// ── formatting helpers ────────────────────────────────────────────────────────
func humanLevel(level slog.Level) string {
@ -137,10 +268,9 @@ func humanLevel(level slog.Level) string {
}
}
func appendAttr(b *strings.Builder, prefix string, a slog.Attr) {
func collectAttr(out *[]string, prefix string, a slog.Attr) {
a.Value = a.Value.Resolve()
if a.Value.Kind() == slog.KindGroup {
// inline unnamed groups; named groups become a key prefix
sub := prefix
if a.Key != "" {
if sub != "" {
@ -149,7 +279,7 @@ func appendAttr(b *strings.Builder, prefix string, a slog.Attr) {
sub += a.Key
}
for _, ga := range a.Value.Group() {
appendAttr(b, sub, ga)
collectAttr(out, sub, ga)
}
return
}
@ -160,10 +290,9 @@ func appendAttr(b *strings.Builder, prefix string, a slog.Attr) {
if prefix != "" {
key = prefix + "." + key
}
b.WriteByte(' ')
b.WriteString(key)
b.WriteByte('=')
appendValue(b, a.Value)
var vb strings.Builder
appendValue(&vb, a.Value)
*out = append(*out, key+"="+vb.String())
}
func appendValue(b *strings.Builder, v slog.Value) {

View File

@ -6,6 +6,8 @@ import (
"testing"
)
// ── humanLevel ────────────────────────────────────────────────────────────────
func TestHumanLevel(t *testing.T) {
tests := []struct {
level slog.Level
@ -24,80 +26,200 @@ func TestHumanLevel(t *testing.T) {
}
}
func TestHumanHandlerInfoNoPrefix(t *testing.T) {
// ── INFO normal mode ──────────────────────────────────────────────────────────
func TestInfoNoFieldsNormalMode(t *testing.T) {
var buf strings.Builder
h := newHumanHandler(&buf, slog.LevelDebug)
slog.New(h).Info("hello world")
slog.New(newHumanHandler(&buf, slog.LevelInfo)).Info("hello world")
if got := strings.TrimRight(buf.String(), "\n"); got != "hello world" {
t.Errorf("got %q, want %q", got, "hello world")
}
}
func TestHumanHandlerPrefixes(t *testing.T) {
tests := []struct {
fn func(*slog.Logger, string, ...any)
want string
}{
{(*slog.Logger).Warn, "warning: "},
{(*slog.Logger).Error, "error: "},
}
for _, tc := range tests {
func TestInfoFieldsHiddenNormalMode(t *testing.T) {
var buf strings.Builder
log := slog.New(newHumanHandler(&buf, slog.LevelDebug))
tc.fn(log, "msg")
if !strings.HasPrefix(buf.String(), tc.want) {
t.Errorf("got %q, want prefix %q", buf.String(), tc.want)
}
slog.New(newHumanHandler(&buf, slog.LevelInfo)).Info("starting", "port", 8080)
got := strings.TrimRight(buf.String(), "\n")
if got != "starting..." {
t.Errorf("got %q, want %q", got, "starting...")
}
}
func TestHumanHandlerAttrs(t *testing.T) {
// ── INFO debug mode ───────────────────────────────────────────────────────────
func TestInfoFieldsVisibleDebugMode(t *testing.T) {
var buf strings.Builder
slog.New(newHumanHandler(&buf, slog.LevelDebug)).Info("started", "port", 8080)
want := "started port=8080\n"
if got := buf.String(); got != want {
t.Errorf("got %q, want %q", got, want)
got := strings.TrimRight(buf.String(), "\n")
if got != "started: port=8080" {
t.Errorf("got %q, want %q", got, "started: port=8080")
}
}
func TestHumanHandlerStringQuoting(t *testing.T) {
var buf strings.Builder
slog.New(newHumanHandler(&buf, slog.LevelDebug)).Warn("check", "msg", "Hello, Gopher!")
// ── WARN / ERROR always full fields ──────────────────────────────────────────
if !strings.Contains(buf.String(), `msg="Hello, Gopher!"`) {
t.Errorf("expected quoted value in %q", buf.String())
func TestWarnFullFieldsNormalMode(t *testing.T) {
var buf strings.Builder
slog.New(newHumanHandler(&buf, slog.LevelInfo)).Warn("check", "key", "val")
if !strings.HasPrefix(buf.String(), "warning: ") {
t.Errorf("missing prefix: %q", buf.String())
}
if !strings.Contains(buf.String(), "key=val") {
t.Errorf("fields missing from WARN: %q", buf.String())
}
}
func TestHumanHandlerWithAttrs(t *testing.T) {
func TestErrorFullFieldsNormalMode(t *testing.T) {
var buf strings.Builder
h := newHumanHandler(&buf, slog.LevelDebug).WithAttrs([]slog.Attr{slog.String("rid", "abc")})
slog.New(h).Info("request")
slog.New(newHumanHandler(&buf, slog.LevelInfo)).Error("failed", "host", "db:5432")
if !strings.HasPrefix(buf.String(), "error: ") {
t.Errorf("missing prefix: %q", buf.String())
}
if !strings.Contains(buf.String(), "host=db:5432") {
t.Errorf("fields missing from ERROR: %q", buf.String())
}
}
// ── DEBUG deduplication ───────────────────────────────────────────────────────
func TestDebugNoFields(t *testing.T) {
var buf strings.Builder
h := newHumanHandler(&buf, slog.LevelDebug)
slog.New(h).Debug("step")
h.flush()
if got := strings.TrimRight(buf.String(), "\n"); got != "debug: step" {
t.Errorf("got %q, want %q", got, "debug: step")
}
}
func TestDebugFieldsHiddenWithEllipsis(t *testing.T) {
var buf strings.Builder
h := newHumanHandler(&buf, slog.LevelDebug)
slog.New(h).Debug("step", "n", 1)
h.flush()
if got := strings.TrimRight(buf.String(), "\n"); got != "debug: step..." {
t.Errorf("got %q, want %q", got, "debug: step...")
}
}
func TestDebugDedupCounter(t *testing.T) {
var buf strings.Builder
h := newHumanHandler(&buf, slog.LevelDebug)
log := slog.New(h)
log.Debug("processing", "n", 1)
log.Debug("processing", "n", 2)
log.Debug("processing", "n", 3)
log.Info("done") // commits the debug line
got := buf.String()
if !strings.Contains(got, "×3") {
t.Errorf("missing counter ×3: %q", got)
}
if !strings.HasSuffix(got, "done\n") {
t.Errorf("should end with done\\n: %q", got)
}
}
func TestDebugDedupCounterNotShownForSingle(t *testing.T) {
var buf strings.Builder
h := newHumanHandler(&buf, slog.LevelDebug)
slog.New(h).Debug("step")
h.flush()
if strings.Contains(buf.String(), "×") {
t.Errorf("counter should not appear for single occurrence: %q", buf.String())
}
}
func TestDebugCommittedByInfo(t *testing.T) {
var buf strings.Builder
h := newHumanHandler(&buf, slog.LevelDebug)
log := slog.New(h)
log.Debug("step")
log.Info("phase complete")
got := buf.String()
// debug line committed (newline written) before INFO
if !strings.Contains(got, "debug: step\n") {
t.Errorf("debug line should be followed by newline: %q", got)
}
if !strings.Contains(got, "phase complete\n") {
t.Errorf("info line should appear: %q", got)
}
}
func TestDebugDifferentMessageResetsCounter(t *testing.T) {
var buf strings.Builder
h := newHumanHandler(&buf, slog.LevelDebug)
log := slog.New(h)
log.Debug("alpha")
log.Debug("beta") // different message — commits alpha, starts beta
h.flush()
got := buf.String()
if !strings.Contains(got, "alpha\n") {
t.Errorf("alpha should be committed with newline: %q", got)
}
if !strings.Contains(got, "beta") {
t.Errorf("beta should appear: %q", got)
}
}
// ── WithAttrs ─────────────────────────────────────────────────────────────────
func TestWithAttrsVisibleOnWarn(t *testing.T) {
var buf strings.Builder
h := newHumanHandler(&buf, slog.LevelInfo).WithAttrs([]slog.Attr{slog.String("rid", "abc")})
slog.New(h).Warn("check")
if !strings.Contains(buf.String(), "rid=abc") {
t.Errorf("pre-set attr missing: %q", buf.String())
t.Errorf("pre-set attr missing from WARN: %q", buf.String())
}
}
func TestHumanHandlerLevelFiltering(t *testing.T) {
func TestWithAttrsHiddenOnInfoNormalMode(t *testing.T) {
var buf strings.Builder
h := newHumanHandler(&buf, slog.LevelInfo).WithAttrs([]slog.Attr{slog.String("rid", "abc")})
slog.New(h).Info("request")
if strings.Contains(buf.String(), "rid") {
t.Errorf("pre-set attrs should be hidden on INFO in normal mode: %q", buf.String())
}
if !strings.Contains(buf.String(), "...") {
t.Errorf("ellipsis should signal hidden attrs: %q", buf.String())
}
}
// ── Level filtering ───────────────────────────────────────────────────────────
func TestLevelFilteringAtWarn(t *testing.T) {
var buf strings.Builder
log := slog.New(newHumanHandler(&buf, slog.LevelWarn))
log.Info("dropped")
log.Warn("kept")
if strings.Contains(buf.String(), "dropped") {
t.Error("INFO line should have been filtered at WARN level")
t.Error("INFO should be filtered at WARN level")
}
if !strings.Contains(buf.String(), "kept") {
t.Error("WARN line should appear")
t.Error("WARN should appear")
}
}
// ── multiHandler fan-out ──────────────────────────────────────────────────────
func TestMultiHandlerFanOut(t *testing.T) {
var screen, file strings.Builder
// screen: INFO+, file: DEBUG+
m := multiHandler{
newHumanHandler(&screen, slog.LevelInfo),
slog.NewJSONHandler(&file, &slog.HandlerOptions{Level: slog.LevelDebug}),
@ -107,7 +229,7 @@ func TestMultiHandlerFanOut(t *testing.T) {
log.Info("event", "k", "v")
if strings.Contains(screen.String(), "trace") {
t.Error("DEBUG should not appear on screen")
t.Error("DEBUG should not appear on screen (handler level is INFO)")
}
if !strings.Contains(screen.String(), "event") {
t.Error("INFO should appear on screen")

View File

@ -85,7 +85,12 @@ func NewCLI(level, debugFile string) result.Expect[*Logger] {
return result.Ok(&Logger{slog.New(h)})
}
screen := newHumanHandler(os.Stderr, slog.LevelInfo)
// debugFile activates debug mode regardless of level; level="debug" also activates it.
screenLevel := slog.LevelInfo
if debugFile != "" || lvl.Value() <= slog.LevelDebug {
screenLevel = slog.LevelDebug
}
screen := newHumanHandler(os.Stderr, screenLevel)
var h slog.Handler = screen
if debugFile != "" {
@ -97,12 +102,7 @@ func NewCLI(level, debugFile string) result.Expect[*Logger] {
h = multiHandler{screen, dump}
}
log := &Logger{slog.New(h)}
if lvl.Value() > slog.LevelInfo {
log.Warn("log level set above INFO — interactive mode always shows INFO and above",
"requested", level)
}
return result.Ok(log)
return result.Ok(&Logger{slog.New(h)})
}
// IsInteractive reports whether stderr is attached to a terminal.
@ -124,6 +124,16 @@ func NewWriter(w io.Writer, level string) result.Expect[*Logger] {
return result.Ok(&Logger{slog.New(h)})
}
// Close flushes any pending debug output. Call defer log.Close() at the entry
// point so a debug line that was never followed by an INFO/WARN/ERROR record
// still gets its trailing newline before the process exits.
func (l *Logger) Close() {
type flusher interface{ flush() }
if f, ok := l.Handler().(flusher); ok {
f.flush()
}
}
// NewNop returns a no-op logger. Useful in tests that don't care about logs.
func NewNop() *Logger {
return &Logger{slog.New(slog.NewTextHandler(io.Discard, nil))}