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

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>

cmd/app/main.go

@@ -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)
 }
 

pkg/logger/handler.go

@@ -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)
+// Normal mode (level > DEBUG):
-//	WARN:  warning: message key=val …
+//
-//	ERROR: error: message key=val …
+//	INFO:  message...          "..." signals hidden structured fields (see debug file)
-//	DEBUG: debug: message key=val …
+//	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()
+// ellipsis builds "prefix message" with "..." appended when structured fields exist.
-	defer h.mu.Unlock()
+func (h *humanHandler) ellipsis(r slog.Record) string {
-	_, err := io.WriteString(h.w, b.String())
+	hasFields := len(h.attrs) > 0
-	return err
+	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,
+// Each sub-handler's own Enabled filter is respected independently.
-// so different handlers can capture different level ranges.
 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(' ')
+	var vb strings.Builder
-	b.WriteString(key)
+	appendValue(&vb, a.Value)
-	b.WriteByte('=')
+	*out = append(*out, key+"="+vb.String())
-	appendValue(b, a.Value)
 }
 
 func appendValue(b *strings.Builder, v slog.Value) {

pkg/logger/handler_test.go

@@ -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(newHumanHandler(&buf, slog.LevelInfo)).Info("hello world")
-	slog.New(h).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) {
+func TestInfoFieldsHiddenNormalMode(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 {
 	var buf strings.Builder
-		log := slog.New(newHumanHandler(&buf, slog.LevelDebug))
+	slog.New(newHumanHandler(&buf, slog.LevelInfo)).Info("starting", "port", 8080)
-		tc.fn(log, "msg")
+
-		if !strings.HasPrefix(buf.String(), tc.want) {
+	got := strings.TrimRight(buf.String(), "\n")
-			t.Errorf("got %q, want prefix %q", buf.String(), tc.want)
+	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"
+	got := strings.TrimRight(buf.String(), "\n")
-	if got := buf.String(); got != want {
+	if got != "started: port=8080" {
-		t.Errorf("got %q, want %q", got, want)
+		t.Errorf("got %q, want %q", got, "started: port=8080")
 	}
 }
 
-func TestHumanHandlerStringQuoting(t *testing.T) {
+// ── WARN / ERROR always full fields ──────────────────────────────────────────
+
+func TestWarnFullFieldsNormalMode(t *testing.T) {
 	var buf strings.Builder
-	slog.New(newHumanHandler(&buf, slog.LevelDebug)).Warn("check", "msg", "Hello, Gopher!")
+	slog.New(newHumanHandler(&buf, slog.LevelInfo)).Warn("check", "key", "val")
 
-	if !strings.Contains(buf.String(), `msg="Hello, Gopher!"`) {
+	if !strings.HasPrefix(buf.String(), "warning: ") {
-		t.Errorf("expected quoted value in %q", buf.String())
+		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(newHumanHandler(&buf, slog.LevelInfo)).Error("failed", "host", "db:5432")
-	slog.New(h).Info("request")
+
+	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")

pkg/logger/logger.go

@@ -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)}
+	return result.Ok(&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)
 }
 
 // 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))}