package diary_test import ( "bytes" "context" "encoding/json" "fmt" "log" "log/slog" "os" "path/filepath" "regexp" "strings" "sync" "testing" "time" "git.golem15.com/golem15/summercms/modules/bonfire" "git.golem15.com/golem15/summercms/modules/compass" "git.golem15.com/golem15/summercms/modules/diary" ) // lockedBuffer is a bytes.Buffer safe for concurrent writers and readers. type lockedBuffer struct { mu sync.Mutex buf bytes.Buffer } func (b *lockedBuffer) Write(p []byte) (int, error) { b.mu.Lock() defer b.mu.Unlock() return b.buf.Write(p) } func (b *lockedBuffer) String() string { b.mu.Lock() defer b.mu.Unlock() return b.buf.String() } func (b *lockedBuffer) Reset() { b.mu.Lock() defer b.mu.Unlock() b.buf.Reset() } // clock is an adjustable time source for Options.Now. type clock struct { mu sync.Mutex t time.Time } func newClock(t time.Time) *clock { return &clock{t: t} } func (c *clock) Now() time.Time { c.mu.Lock() defer c.mu.Unlock() return c.t } func (c *clock) Set(t time.Time) { c.mu.Lock() defer c.mu.Unlock() c.t = t } // day is a local time on 2026-10- at hh:mm:ss. func day(d, hh, mm, ss int) time.Time { return time.Date(2026, 10, d, hh, mm, ss, 0, time.Local) } // setup runs diary.Setup with a configuration opened from environ (no // config files) and registers diary.Reset as cleanup. Unset Options fields // get test defaults: no color, a fresh root and a fixed clock. func setup(t *testing.T, opts diary.Options, environ ...string) { t.Helper() if opts.Root == "" { opts.Root = t.TempDir() } if opts.Environ == nil { opts.Environ = []string{} } if opts.Now == nil { opts.Now = func() time.Time { return day(21, 12, 0, 0) } } t.Cleanup(diary.Reset) if err := diary.Setup(openConfig(t, environ...), opts); err != nil { t.Fatalf("Setup: %v", err) } } // keepDefault restores the process default logger and the log package's // output and flags after the test. func keepDefault(t *testing.T) { t.Helper() prev, w, flags := slog.Default(), log.Writer(), log.Flags() t.Cleanup(func() { slog.SetDefault(prev) log.SetOutput(w) log.SetFlags(flags) }) } // readDaily returns the lines of a daily file, closing the writers first. func readDaily(t *testing.T, path string) []string { t.Helper() if err := diary.Close(); err != nil { t.Fatalf("Close: %v", err) } raw, err := os.ReadFile(path) if err != nil { t.Fatalf("read daily file: %v", err) } text := strings.TrimSpace(string(raw)) if text == "" { return nil } return strings.Split(text, "\n") } // TestComponentFloors: a component's log.components level beats log.level, // and records without a component use log.level. func TestComponentFloors(t *testing.T) { var buf lockedBuffer setup(t, diary.Options{Stderr: &buf}, "SUMMER_LOG__DEFAULT=console", "SUMMER_LOG__LEVEL=warn", "SUMMER_LOG__COMPONENTS__JOURNAL=debug", "SUMMER_LOG__COMPONENTS__RIVER=error", ) diary.For("journal").Debug("journal debug") diary.For("river").Warn("river warn") diary.For("river").Error("river error") diary.For("blog").Info("blog info") diary.For("blog").Warn("blog warn") slog.Info("default info") slog.Warn("default warn") out := buf.String() for _, want := range []string{"journal debug", "river error", "blog warn", "default warn"} { if !strings.Contains(out, want) { t.Errorf("console lacks %q:\n%s", want, out) } } for _, unwanted := range []string{"river warn", "blog info", "default info"} { if strings.Contains(out, unwanted) { t.Errorf("console has %q below its floor:\n%s", unwanted, out) } } } // TestVerbosityLevels: verbosity 1 lets info through for a warn component, // 2 lets debug through, 3 adds source locations on styled console lines. func TestVerbosityLevels(t *testing.T) { var buf lockedBuffer setup(t, diary.Options{Stderr: &buf}, "SUMMER_LOG__DEFAULT=console") river, blog := diary.For("river"), diary.For("blog") river.Info("river info v0") river.Warn("river warn v0") blog.Debug("blog debug v0") diary.SetVerbosity(1, false) if diary.Verbosity() != 1 { t.Fatalf("Verbosity() = %d, want 1", diary.Verbosity()) } river.Info("river info v1") blog.Debug("blog debug v1") diary.SetVerbosity(2, false) river.Debug("river debug v2") blog.Debug("blog debug v2") out := buf.String() for _, want := range []string{"river warn v0", "river info v1", "river debug v2", "blog debug v2"} { if !strings.Contains(out, want) { t.Errorf("console lacks %q:\n%s", want, out) } } for _, unwanted := range []string{"river info v0", "blog debug v0", "blog debug v1"} { if strings.Contains(out, unwanted) { t.Errorf("console has %q:\n%s", unwanted, out) } } // Source locations need the styled console. var styled lockedBuffer diary.Reset() setup(t, diary.Options{Stderr: &styled, Color: bonfire.ColorAlways, Verbosity: 2}) blog.Info("no source at v2") diary.SetVerbosity(3, false) blog.Info("source at v3") lines := strings.Split(strings.TrimSpace(styled.String()), "\n") if len(lines) != 2 { t.Fatalf("styled console has %d lines, want 2:\n%s", len(lines), styled.String()) } if strings.Contains(lines[0], "diary_test.go:") { t.Errorf("verbosity 2 line carries a source location: %q", lines[0]) } if !strings.Contains(lines[1], "diary_test.go:") { t.Errorf("verbosity 3 line lacks the source location: %q", lines[1]) } // Options.Verbosity 3 at setup switches source on too. styled.Reset() diary.Reset() setup(t, diary.Options{Stderr: &styled, Color: bonfire.ColorAlways, Verbosity: 3}) blog.Info("source from options") if !strings.Contains(styled.String(), "diary_test.go:") { t.Errorf("Options.Verbosity 3 line lacks the source location:\n%s", styled.String()) } } // TestQuietConsoleOnly: quiet raises the console channels to warn while the // daily file keeps its own level. func TestQuietConsoleOnly(t *testing.T) { var buf lockedBuffer root := t.TempDir() setup(t, diary.Options{Stderr: &buf, Root: root, Quiet: true}, "SUMMER_LOG__CHANNELS__DAILY__LEVEL=info") blog := diary.For("blog") blog.Info("info while quiet") blog.Warn("warn while quiet") out := buf.String() if strings.Contains(out, "info while quiet") { t.Errorf("quiet console shows an info record:\n%s", out) } if !strings.Contains(out, "warn while quiet") { t.Errorf("quiet console lacks the warning:\n%s", out) } lines := readDaily(t, filepath.Join(root, "storage", "logs", "summer-2026-10-21.log")) daily := strings.Join(lines, "\n") for _, want := range []string{"info while quiet", "warn while quiet"} { if !strings.Contains(daily, want) { t.Errorf("daily file lacks %q under quiet:\n%s", want, daily) } } // Quiet beats verbosity on the console; leaving quiet restores info. buf.Reset() diary.SetVerbosity(2, true) blog.Info("info at -vv -q") diary.SetVerbosity(0, false) blog.Info("info after quiet") out = buf.String() if strings.Contains(out, "info at -vv -q") { t.Errorf("quiet console shows info at verbosity 2:\n%s", out) } if !strings.Contains(out, "info after quiet") { t.Errorf("console lacks info after quiet was switched off:\n%s", out) } } // preSetupLogger is created before any setup, as module loggers are. var preSetupLogger = diary.For("early") // TestForBeforeSetup: a logger created before setup writes to the process // default logger until Setup, then to the configured channels, including // the loggers derived from it with With and WithGroup. func TestForBeforeSetup(t *testing.T) { keepDefault(t) diary.Reset() var before bytes.Buffer slog.SetDefault(slog.New(slog.NewTextHandler(&before, nil))) derived := preSetupLogger.With("k", "v").WithGroup("g") preSetupLogger.Info("before setup") derived.Info("derived before", "a", 1) for _, want := range []string{"component=early", "before setup", "k=v", "g.a=1"} { if !strings.Contains(before.String(), want) { t.Errorf("process default lacks %q:\n%s", want, before.String()) } } var after lockedBuffer setup(t, diary.Options{Stderr: &after}, "SUMMER_LOG__DEFAULT=console") before.Reset() preSetupLogger.Info("after setup") derived.Info("derived after", "a", 2) if before.Len() != 0 { t.Errorf("process default still receives records after Setup:\n%s", before.String()) } for _, want := range []string{"component=early", "after setup", "derived after", "k=v", "g.a=2"} { if !strings.Contains(after.String(), want) { t.Errorf("configured console lacks %q:\n%s", want, after.String()) } } } // TestResetRestoresDefault: Reset puts back the process default logger and // the log package's output captured at the first setup. func TestResetRestoresDefault(t *testing.T) { keepDefault(t) diary.Reset() var own, std bytes.Buffer custom := slog.New(slog.NewTextHandler(&own, nil)) slog.SetDefault(custom) log.SetOutput(&std) log.SetFlags(0) var buf lockedBuffer setup(t, diary.Options{Stderr: &buf, Verbosity: 2}, "SUMMER_LOG__DEFAULT=console") if slog.Default() == custom { t.Fatal("Setup did not install diary as the process default") } log.Print("through the log package") if !strings.Contains(buf.String(), "through the log package") { t.Errorf("log package output does not reach diary:\n%s", buf.String()) } diary.Reset() if slog.Default() != custom { t.Error("Reset did not restore the previous process default logger") } if log.Writer() != &std { t.Error("Reset did not restore the log package's output") } if diary.Verbosity() != 0 { t.Errorf("Verbosity() = %d after Reset, want 0", diary.Verbosity()) } diary.For("x").Info("after reset") if !strings.Contains(own.String(), "after reset") { t.Errorf("record after Reset did not reach the restored default:\n%s", own.String()) } } // TestNoRecursionWithoutState: with no setup and a diary logger as the // process default, a component logger falls back instead of recursing. func TestNoRecursionWithoutState(t *testing.T) { keepDefault(t) diary.Reset() slog.SetDefault(diary.For("loop")) done := make(chan struct{}) go func() { defer close(done) diary.For("x").Debug("dropped by the fallback level") diary.For("x").Warn("diary fallback probe (expected on stderr)") }() select { case <-done: case <-time.After(10 * time.Second): t.Fatal("logging without state did not return") } } // TestHideOnTTY: records logged with HideOnTTY are skipped by the styled // console only; a plain console and the daily file keep them. func TestHideOnTTY(t *testing.T) { ctx := diary.HideOnTTY(context.Background()) if diary.HideOnTTY(nil) == nil { //nolint:staticcheck // a nil context is accepted t.Fatal("HideOnTTY(nil) returned nil") } var styled lockedBuffer root := t.TempDir() setup(t, diary.Options{Stderr: &styled, Color: bonfire.ColorAlways, Root: root}, "SUMMER_LOG__CHANNELS__DAILY__LEVEL=info") blog := diary.For("blog") blog.InfoContext(ctx, "hidden summary") blog.Info("shown line") if strings.Contains(styled.String(), "hidden summary") { t.Errorf("styled console shows a HideOnTTY record:\n%s", styled.String()) } if !strings.Contains(styled.String(), "shown line") { t.Errorf("styled console lacks the ordinary record:\n%s", styled.String()) } daily := strings.Join(readDaily(t, filepath.Join(root, "storage", "logs", "summer-2026-10-21.log")), "\n") if !strings.Contains(daily, "hidden summary") { t.Errorf("daily file lacks the HideOnTTY record:\n%s", daily) } diary.Reset() var plain lockedBuffer setup(t, diary.Options{Stderr: &plain}, "SUMMER_LOG__DEFAULT=console") blog.InfoContext(ctx, "hidden summary") if !strings.Contains(plain.String(), "hidden summary") { t.Errorf("plain console off a terminal dropped a HideOnTTY record:\n%s", plain.String()) } } // TestConcurrentWrites: 100 goroutines logging at once (with verbosity // changes in between) leave every console line and every daily line intact. func TestConcurrentWrites(t *testing.T) { const writers, perWriter = 100, 20 var buf lockedBuffer root := t.TempDir() setup(t, diary.Options{Stderr: &buf, Root: root}, "SUMMER_LOG__CHANNELS__DAILY__LEVEL=info") logger := diary.For("worker") var wg sync.WaitGroup for g := range writers { wg.Add(1) go func() { defer wg.Done() l := logger.With("g", g) for n := range perWriter { l.Info("concurrent write", "n", n) } }() } wg.Add(1) go func() { defer wg.Done() for i := range 50 { diary.SetVerbosity(i%2, false) } }() wg.Wait() line := regexp.MustCompile(`^time=\S+ level=INFO msg="concurrent write" component=worker g=(\d+) n=(\d+)$`) seen := map[string]bool{} for _, l := range strings.Split(strings.TrimSpace(buf.String()), "\n") { m := line.FindStringSubmatch(l) if m == nil { t.Fatalf("garbled console line: %q", l) } seen[m[1]+"/"+m[2]] = true } if len(seen) != writers*perWriter { t.Errorf("console has %d distinct records, want %d", len(seen), writers*perWriter) } lines := readDaily(t, filepath.Join(root, "storage", "logs", "summer-2026-10-21.log")) if len(lines) != writers*perWriter { t.Fatalf("daily file has %d lines, want %d", len(lines), writers*perWriter) } daily := map[string]bool{} for _, l := range lines { var rec map[string]any if err := json.Unmarshal([]byte(l), &rec); err != nil { t.Fatalf("garbled daily line %q: %v", l, err) } if rec["msg"] != "concurrent write" || rec["component"] != "worker" { t.Fatalf("unexpected daily record %v", rec) } daily[fmt.Sprint(rec["g"], "/", rec["n"])] = true } if len(daily) != writers*perWriter { t.Errorf("daily file has %d distinct records, want %d", len(daily), writers*perWriter) } } // TestRedactionEveryDriver: every writing driver redacts sensitive // attributes and scrubs Bearer tokens from the message; null writes nothing. func TestRedactionEveryDriver(t *testing.T) { secrets := []string{"pw-value-1", "tok-value-2", "key-value-3", "pw-nested-4", "abc.def.ghi"} logSecrets := func() { diary.For("auth").Warn("calling upstream with Bearer abc.def.ghi", "password", "pw-value-1", "token", "tok-value-2", "api_key", "key-value-3", slog.Group("nested", "password", "pw-nested-4")) } check := func(t *testing.T, where, out string) { t.Helper() for _, s := range secrets { if strings.Contains(out, s) { t.Errorf("%s leaks %q:\n%s", where, s, out) } } if strings.Count(out, "[REDACTED]") < 5 { t.Errorf("%s has fewer than five [REDACTED] markers:\n%s", where, out) } if !strings.Contains(out, "Bearer [REDACTED]") { t.Errorf("%s does not scrub the Bearer token:\n%s", where, out) } } dailyFile := func(root string) string { return filepath.Join(root, "storage", "logs", "summer-2026-10-21.log") } cases := []struct { name string color bonfire.ColorMode environ []string console bool daily bool }{ {"console logfmt", bonfire.ColorNever, []string{"SUMMER_LOG__DEFAULT=console"}, true, false}, {"console styled", bonfire.ColorAlways, []string{"SUMMER_LOG__DEFAULT=console"}, true, false}, {"console json", bonfire.ColorNever, []string{"SUMMER_LOG__DEFAULT=console", "SUMMER_LOG__CHANNELS__CONSOLE__FORMAT=json"}, true, false}, {"stderr logfmt", bonfire.ColorNever, []string{"SUMMER_LOG__DEFAULT=stderr"}, true, false}, {"stderr json", bonfire.ColorNever, []string{"SUMMER_LOG__DEFAULT=stderr", "SUMMER_LOG__CHANNELS__STDERR__FORMAT=json"}, true, false}, {"daily", bonfire.ColorNever, []string{"SUMMER_LOG__DEFAULT=daily"}, false, true}, {"daily logfmt", bonfire.ColorNever, []string{"SUMMER_LOG__DEFAULT=daily", "SUMMER_LOG__CHANNELS__DAILY__FORMAT=logfmt"}, false, true}, {"stack", bonfire.ColorNever, nil, true, true}, } for _, tc := range cases { t.Run(tc.name, func(t *testing.T) { var buf lockedBuffer root := t.TempDir() setup(t, diary.Options{Stderr: &buf, Root: root, Color: tc.color}, tc.environ...) logSecrets() if tc.console { check(t, "console", buf.String()) } else if buf.String() != "" { t.Errorf("console written although the channel is %s:\n%s", tc.name, buf.String()) } if tc.daily { check(t, "daily file", strings.Join(readDaily(t, dailyFile(root)), "\n")) } }) } t.Run("null", func(t *testing.T) { var buf lockedBuffer root := t.TempDir() setup(t, diary.Options{Stderr: &buf, Root: root}, "SUMMER_LOG__DEFAULT=null") logSecrets() if buf.String() != "" { t.Errorf("null channel wrote to the console:\n%s", buf.String()) } entries, err := os.ReadDir(root) if err != nil { t.Fatal(err) } if len(entries) != 0 { t.Errorf("null channel created files: %v", entries) } }) } // openYAMLConfig opens a compass config whose config/log.yaml holds text. func openYAMLConfig(t *testing.T, text string, environ ...string) *compass.Config { t.Helper() dir := filepath.Join(t.TempDir(), "config") if err := os.MkdirAll(dir, 0o755); err != nil { t.Fatal(err) } if err := os.WriteFile(filepath.Join(dir, "log.yaml"), []byte(text), 0o644); err != nil { t.Fatal(err) } cfg, err := compass.Open(compass.Options{Dir: dir, Environ: append([]string{}, environ...)}) if err != nil { t.Fatal(err) } return cfg }