summercms/modules/diary/diary_test.go

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-<d> 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
}