From 7bc91b0890a3a6caeb83090ebe0cdc71530b9d7c Mon Sep 17 00:00:00 2001 From: djmil Date: Wed, 3 Jun 2026 14:14:19 +0000 Subject: [PATCH] pkg/logger: replace NewDevelopment with NewCLI(level, debugFile) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two modes for interactive CLI use — driven by debugFile presence: - Normal (debugFile=""): human text on screen, INFO and above. - Debug (debugFile set): same screen + full JSON trace to file. Auto-detects TTY; falls back to 12-factor JSON when piped/redirected. IsInteractive() exposes TTY detection for call sites that need it. Terminal format: INFO has no prefix (program's normal voice); WARN prints "warning: …"; ERROR prints "error: …"; DEBUG "debug: …". Breaking: NewDevelopment removed. Co-Authored-By: Claude Sonnet 4.6 --- cmd/app/config.go | 7 +- cmd/app/main.go | 14 ++- pkg/logger/handler.go | 183 +++++++++++++++++++++++++++++++++++++ pkg/logger/handler_test.go | 121 ++++++++++++++++++++++++ pkg/logger/logger.go | 92 ++++++++++++++----- pkg/logger/logger_test.go | 25 +++++ 6 files changed, 411 insertions(+), 31 deletions(-) create mode 100644 pkg/logger/handler.go create mode 100644 pkg/logger/handler_test.go diff --git a/cmd/app/config.go b/cmd/app/config.go index 4d2d4f5..945f307 100644 --- a/cmd/app/config.go +++ b/cmd/app/config.go @@ -19,7 +19,8 @@ type AppConfig struct { // LoggerConfig controls logging behavior. type LoggerConfig struct { - Level string // debug | info | warn | error + Level string // debug | info | warn | error + DebugFile string // non-empty enables debug mode: writes full JSON trace to this path } // Greeter config for internal/greeter/Service. @@ -41,6 +42,7 @@ func parseArgs() *Config { port := flag.Int("port", 8080, "listen port") env := flag.String("env", "dev", "environment: dev | staging | prod") level := flag.String("log-level", "info", "log level: debug | info | warn | error") + debugLog := flag.String("debug-log", "", "write full debug trace to file (enables debug mode)") flag.Parse() @@ -50,7 +52,8 @@ func parseArgs() *Config { Env: *env, }, Logger: LoggerConfig{ - Level: *level, + Level: *level, + DebugFile: *debugLog, }, Greeter: GreeterConfig{ Name: *name, diff --git a/cmd/app/main.go b/cmd/app/main.go index 5555e42..4ba6360 100644 --- a/cmd/app/main.go +++ b/cmd/app/main.go @@ -22,11 +22,12 @@ type app struct { } func newApp(cfg *Config) *app { - var log *logger.Logger + // NewCLI auto-detects: human text on a terminal, JSON when piped. + // Pass -debug-log FILE to enable debug mode (writes full trace to file). + log := logger.NewCLI(cfg.Logger.Level, cfg.Logger.DebugFile).Expect("create logger") + log.Debug("config", "port", cfg.App.Port, "level", cfg.Logger.Level, "env", cfg.App.Env) if cfg.App.Env == "dev" { - log = logger.NewDevelopment() - } else { - log = logger.New(cfg.Logger.Level).Expect("create logger") // might fail dramatically + log.Warn("dev mode — not for production") } return &app{ cfg: cfg, @@ -54,11 +55,8 @@ func main() { } func (a *app) run() { - // High level business logic goes here + a.log.Debug("processing", "name", a.cfg.Greeter.Name) a.showGreeting(a.cfg.Greeter.Name) - - // Human readable messages. - // Use logs for presenting technical data in machine friendly format. 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 new file mode 100644 index 0000000..54b5e0a --- /dev/null +++ b/pkg/logger/handler.go @@ -0,0 +1,183 @@ +package logger + +import ( + "context" + "fmt" + "io" + "log/slog" + "os" + "strconv" + "strings" + "sync" + "time" +) + +// isTerminal reports whether f is connected to a character device (terminal). +func isTerminal(f *os.File) bool { + info, err := f.Stat() + return err == nil && info.Mode()&os.ModeCharDevice != 0 +} + +// humanHandler writes human-readable log lines to w with no timestamp. +// +// Format: +// +// 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 … +type humanHandler struct { + w io.Writer + level slog.Level + mu sync.Mutex + attrs []slog.Attr + prefix string // dot-separated group prefix for attribute keys +} + +func newHumanHandler(w io.Writer, level slog.Level) *humanHandler { + return &humanHandler{w: w, level: level} +} + +func (h *humanHandler) Enabled(_ context.Context, level slog.Level) bool { + return level >= h.level +} + +func (h *humanHandler) Handle(_ context.Context, r slog.Record) error { + var b strings.Builder + b.WriteString(humanLevel(r.Level)) + b.WriteString(r.Message) + + for _, a := range h.attrs { + appendAttr(&b, h.prefix, a) + } + r.Attrs(func(a slog.Attr) bool { + appendAttr(&b, h.prefix, a) + return true + }) + b.WriteByte('\n') + + h.mu.Lock() + defer h.mu.Unlock() + _, err := io.WriteString(h.w, b.String()) + return err +} + +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} +} + +func (h *humanHandler) WithGroup(name string) slog.Handler { + if name == "" { + return h + } + prefix := h.prefix + if prefix != "" { + prefix += "." + } + return &humanHandler{w: h.w, level: h.level, 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. +type multiHandler []slog.Handler + +func (m multiHandler) Enabled(ctx context.Context, level slog.Level) bool { + for _, h := range m { + if h.Enabled(ctx, level) { + return true + } + } + return false +} + +func (m multiHandler) Handle(ctx context.Context, r slog.Record) error { + var firstErr error + for _, h := range m { + if h.Enabled(ctx, r.Level) { + if err := h.Handle(ctx, r); err != nil && firstErr == nil { + firstErr = err + } + } + } + return firstErr +} + +func (m multiHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + handlers := make(multiHandler, len(m)) + for i, h := range m { + handlers[i] = h.WithAttrs(attrs) + } + return handlers +} + +func (m multiHandler) WithGroup(name string) slog.Handler { + handlers := make(multiHandler, len(m)) + for i, h := range m { + handlers[i] = h.WithGroup(name) + } + return handlers +} + +// ── formatting helpers ──────────────────────────────────────────────────────── + +func humanLevel(level slog.Level) string { + switch { + case level >= slog.LevelError: + return "error: " + case level >= slog.LevelWarn: + return "warning: " + case level >= slog.LevelInfo: + return "" // INFO needs no label — it is the program's normal voice + default: + return "debug: " + } +} + +func appendAttr(b *strings.Builder, 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 != "" { + sub += "." + } + sub += a.Key + } + for _, ga := range a.Value.Group() { + appendAttr(b, sub, ga) + } + return + } + if a.Key == "" { + return + } + key := a.Key + if prefix != "" { + key = prefix + "." + key + } + b.WriteByte(' ') + b.WriteString(key) + b.WriteByte('=') + appendValue(b, a.Value) +} + +func appendValue(b *strings.Builder, v slog.Value) { + switch v.Kind() { + case slog.KindString: + s := v.String() + if strings.ContainsAny(s, " \t\n\"=") { + b.WriteString(strconv.Quote(s)) + } else { + b.WriteString(s) + } + case slog.KindTime: + b.WriteString(v.Time().Format(time.RFC3339)) + default: + fmt.Fprint(b, v.Any()) + } +} diff --git a/pkg/logger/handler_test.go b/pkg/logger/handler_test.go new file mode 100644 index 0000000..77622f0 --- /dev/null +++ b/pkg/logger/handler_test.go @@ -0,0 +1,121 @@ +package logger + +import ( + "log/slog" + "strings" + "testing" +) + +func TestHumanLevel(t *testing.T) { + tests := []struct { + level slog.Level + want string + }{ + {slog.LevelDebug, "debug: "}, + {slog.LevelInfo, ""}, + {slog.LevelWarn, "warning: "}, + {slog.LevelError, "error: "}, + {slog.LevelError + 4, "error: "}, + } + for _, tc := range tests { + if got := humanLevel(tc.level); got != tc.want { + t.Errorf("humanLevel(%v) = %q, want %q", tc.level, got, tc.want) + } + } +} + +func TestHumanHandlerInfoNoPrefix(t *testing.T) { + var buf strings.Builder + h := newHumanHandler(&buf, slog.LevelDebug) + 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) { + 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 TestHumanHandlerAttrs(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) + } +} + +func TestHumanHandlerStringQuoting(t *testing.T) { + var buf strings.Builder + slog.New(newHumanHandler(&buf, slog.LevelDebug)).Warn("check", "msg", "Hello, Gopher!") + + if !strings.Contains(buf.String(), `msg="Hello, Gopher!"`) { + t.Errorf("expected quoted value in %q", buf.String()) + } +} + +func TestHumanHandlerWithAttrs(t *testing.T) { + var buf strings.Builder + h := newHumanHandler(&buf, slog.LevelDebug).WithAttrs([]slog.Attr{slog.String("rid", "abc")}) + slog.New(h).Info("request") + + if !strings.Contains(buf.String(), "rid=abc") { + t.Errorf("pre-set attr missing: %q", buf.String()) + } +} + +func TestHumanHandlerLevelFiltering(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") + } + if !strings.Contains(buf.String(), "kept") { + t.Error("WARN line should appear") + } +} + +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}), + } + log := slog.New(m) + log.Debug("trace", "k", "v") + log.Info("event", "k", "v") + + if strings.Contains(screen.String(), "trace") { + t.Error("DEBUG should not appear on screen") + } + if !strings.Contains(screen.String(), "event") { + t.Error("INFO should appear on screen") + } + if !strings.Contains(file.String(), "trace") { + t.Error("DEBUG should appear in file") + } + if !strings.Contains(file.String(), "event") { + t.Error("INFO should appear in file") + } +} diff --git a/pkg/logger/logger.go b/pkg/logger/logger.go index 3e2a050..b8464f2 100644 --- a/pkg/logger/logger.go +++ b/pkg/logger/logger.go @@ -1,16 +1,26 @@ // Package logger wraps log/slog with a thin, ergonomic API. // -// Per the Twelve-Factor App (factor XI), the application writes structured log -// events to stderr and never manages log files or routing itself. The execution -// environment (shell, systemd, Docker) is responsible for capturing and storing -// the stream. Human-readable output belongs on stdout via fmt.Print*. +// Design principle: call sites express what is logged, not how it reaches the +// reader. The constructor picks the right format for the execution environment; +// application code never changes. // -// Typical use: +// Per the Twelve-Factor App (factor XI), logs are written to stderr as an +// unbuffered stream. The execution environment (shell, systemd, Docker, k8s) +// routes and stores the stream. // -// log := logger.New("info").Expect("create logger") +// Two constructors write to stderr: +// +// - New(level) — JSON, 12-factor compatible; use for headless services. +// - NewCLI(level, debugFile) — auto-detects: human text on a terminal, JSON when piped. +// Providing a non-empty debugFile enables debug mode: DEBUG writes to that +// file as JSON; the screen always shows INFO and above. +// +// Typical use in a CLI application: +// +// log := logger.NewCLI("info", "").Expect("create logger") // log.Info("server started", "port", 8080) // -// // child logger for request-scoped fields that repeat across many lines: +// // child logger with request-scoped fields: // req := log.WithField("request_id", rid) // req.Info("start") // req.Info("end") @@ -38,6 +48,7 @@ type Logger struct { } // New creates a JSON logger writing to stderr for the given level string. +// Use for headless services; prefer NewCLI for programs invoked by a human. // Valid levels: debug, info, warn, error. func New(level string) result.Expect[*Logger] { lvl := parseLevel(level) @@ -45,18 +56,60 @@ func New(level string) result.Expect[*Logger] { return result.Errw[*Logger](lvl.Err(), "parse log level") } - handler := slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{Level: lvl.Value()}) - logger := &Logger{slog.New(handler)} - - return result.Ok(logger) + h := slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{Level: lvl.Value()}) + return result.Ok(&Logger{slog.New(h)}) } -// NewDevelopment creates a human-friendly text logger writing to stderr at debug level. -// Use this in local dev; prefer New() in any deployed environment. -func NewDevelopment() *Logger { - h := slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{Level: slog.LevelDebug}) +// NewCLI creates a logger for programs invoked by a human operator. +// +// When stderr is a terminal it operates in one of two modes: +// - Normal (debugFile == ""): human-readable text, INFO and above on screen. +// - Debug (debugFile != ""): same screen output, plus a full JSON trace of +// DEBUG and above written to debugFile for post-run investigation. +// +// When stderr is not a terminal (piped or redirected), NewCLI behaves like +// New: JSON at the given level to stderr; debugFile is ignored. +// +// Passing a level above "info" when running in a terminal is unusual — +// NewCLI will log a warning because interactive mode always shows INFO and above. +// +// Valid levels: debug, info, warn, error. +func NewCLI(level, debugFile string) result.Expect[*Logger] { + lvl := parseLevel(level) + if lvl.Err() != nil { + return result.Errw[*Logger](lvl.Err(), "parse log level") + } - return &Logger{slog.New(h)} + if !isTerminal(os.Stderr) { + h := slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{Level: lvl.Value()}) + return result.Ok(&Logger{slog.New(h)}) + } + + screen := newHumanHandler(os.Stderr, slog.LevelInfo) + + var h slog.Handler = screen + if debugFile != "" { + f, err := os.Create(debugFile) + if err != nil { + return result.Errw[*Logger](err, "create debug log") + } + dump := slog.NewJSONHandler(f, &slog.HandlerOptions{Level: slog.LevelDebug}) + 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) +} + +// IsInteractive reports whether stderr is attached to a terminal. +// Use this when the application itself needs to adjust behavior based on +// whether a human operator is watching (e.g. progress bars, prompts). +func IsInteractive() bool { + return isTerminal(os.Stderr) } // NewWriter creates a JSON logger writing to w. Intended for tests that need to @@ -67,9 +120,8 @@ func NewWriter(w io.Writer, level string) result.Expect[*Logger] { return result.Errw[*Logger](lvl.Err(), "parse log level") } - handler := slog.NewJSONHandler(w, &slog.HandlerOptions{Level: lvl.Value()}) - - return result.Ok(&Logger{slog.New(handler)}) + h := slog.NewJSONHandler(w, &slog.HandlerOptions{Level: lvl.Value()}) + return result.Ok(&Logger{slog.New(h)}) } // NewNop returns a no-op logger. Useful in tests that don't care about logs. @@ -90,7 +142,6 @@ func (l *Logger) WithFields(fields map[string]any) *Logger { for k, v := range fields { args = append(args, k, v) } - return &Logger{l.Logger.With(args...)} } @@ -101,6 +152,5 @@ func parseLevel(level string) result.Expect[slog.Level] { if err := lvl.UnmarshalText([]byte(level)); err != nil { return result.Errw[slog.Level](err, "unknown level (use debug|info|warn|error)") } - return result.Ok(lvl) } diff --git a/pkg/logger/logger_test.go b/pkg/logger/logger_test.go index 110b3d3..2deae81 100644 --- a/pkg/logger/logger_test.go +++ b/pkg/logger/logger_test.go @@ -7,6 +7,31 @@ import ( "gitea.djmil.dev/go/template/pkg/testutil" ) +func TestNewCLI(t *testing.T) { + tests := []struct { + level string + wantErr bool + }{ + {level: "debug"}, + {level: "info"}, + {level: "warn"}, + {level: "error"}, + {level: "invalid", wantErr: true}, + {level: "", wantErr: true}, + } + for _, tc := range tests { + t.Run(tc.level, func(t *testing.T) { + // In tests stderr is not a terminal — NewCLI uses JSON path. + r := logger.NewCLI(tc.level, "") + if tc.wantErr { + testutil.ResultErr(t, r) + return + } + testutil.ResultOkNotNil(t, r) + }) + } +} + func TestNew(t *testing.T) { tests := []struct { level string