diff --git a/cmd/app/main.go b/cmd/app/main.go index 4ba6360..114b98c 100644 --- a/cmd/app/main.go +++ b/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) } diff --git a/pkg/logger/handler.go b/pkg/logger/handler.go index 54b5e0a..30580e0 100644 --- a/pkg/logger/handler.go +++ b/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) -// 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) { diff --git a/pkg/logger/handler_test.go b/pkg/logger/handler_test.go index 77622f0..9744ef9 100644 --- a/pkg/logger/handler_test.go +++ b/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(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 { - 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) - } +func TestInfoFieldsHiddenNormalMode(t *testing.T) { + var buf strings.Builder + 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") diff --git a/pkg/logger/logger.go b/pkg/logger/logger.go index b8464f2..6ede106 100644 --- a/pkg/logger/logger.go +++ b/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)} - 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))}