test(diary): config, channels, rotation, redaction and slogtest
- config rules name their key; env strings overlay defaults; D-08 defaults - component floors, verbosity 1-3, quiet on the console only - daily rotation, retention, 0640 files, unwritable dir, lazy open, path confinement - redaction on every driver, console control-character stripping and prefix - loggers before Setup, Reset, HideOnTTY, 100 concurrent writers - testing/slogtest for the console handler and the JSON pipeline - sunscreen InstallDefault still installs a redacting logfmt handler
This commit is contained in:
Jakub Zych
202
modules/diary/config_test.go
Normal file
202
modules/diary/config_test.go
Normal file
@@ -0,0 +1,202 @@
|
||||
package diary_test
|
||||
|
||||
import (
|
||||
"log/slog"
|
||||
"os"
|
||||
"path/filepath"
|
||||
"reflect"
|
||||
"strings"
|
||||
"testing"
|
||||
|
||||
"git.golem15.com/golem15/summercms/modules/diary"
|
||||
)
|
||||
|
||||
// TestConfigRules: every invalid value in config/log.yaml fails with an
|
||||
// error naming its exact key; YAML lists and comma strings parse alike.
|
||||
func TestConfigRules(t *testing.T) {
|
||||
cases := []struct {
|
||||
name string
|
||||
yaml string
|
||||
key string
|
||||
}{
|
||||
{"level", "level: loud\n", "log.level"},
|
||||
{"default undefined", "default: nowhere\n", "log.default"},
|
||||
{"default empty", "default: \"\"\n", "log.default"},
|
||||
{"driver", "channels:\n daily:\n driver: syslog\n", "log.channels.daily.driver"},
|
||||
{"driver missing", "channels:\n extra:\n level: info\n", "log.channels.extra.driver"},
|
||||
{"format", "channels:\n console:\n format: xml\n", "log.channels.console.format"},
|
||||
{"auto outside console", "channels:\n stderr:\n format: auto\n", "log.channels.stderr.format"},
|
||||
{"channel level", "channels:\n daily:\n level: chatty\n", "log.channels.daily.level"},
|
||||
{"days negative", "channels:\n daily:\n days: -3\n", "log.channels.daily.days"},
|
||||
{"days fraction", "channels:\n daily:\n days: 1.5\n", "log.channels.daily.days"},
|
||||
{"days text", "channels:\n daily:\n days: often\n", "log.channels.daily.days"},
|
||||
{"unknown setting", "channels:\n daily:\n rotate: hourly\n", "log.channels.daily.rotate"},
|
||||
{"channel not a map", "channels:\n daily: yes\n", "log.channels.daily"},
|
||||
{"daily path missing", "channels:\n daily:\n path: \"\"\n", "log.channels.daily.path"},
|
||||
{"path escapes", "channels:\n daily:\n path: ../outside/summer.log\n", "log.channels.daily.path"},
|
||||
{"path escapes after clean", "channels:\n daily:\n path: storage/../../outside.log\n", "log.channels.daily.path"},
|
||||
{"stack empty", "channels:\n stack:\n channels: []\n", "log.channels.stack.channels"},
|
||||
{"stack child", "channels:\n stack:\n channels: [console, nowhere]\n", "log.channels.stack.channels"},
|
||||
{"stack self", "channels:\n stack:\n channels: [console, stack]\n", "log.channels.stack.channels"},
|
||||
{"stack cycle", "default: a\nchannels:\n a:\n driver: stack\n channels: [console, b]\n b:\n driver: stack\n channels: [a]\n", "log.channels.a.channels"},
|
||||
{"component level", "components:\n river: chatty\n", "log.components.river"},
|
||||
{"component nested", "components:\n golem15:\n blog: info\n", "log.components.golem15"},
|
||||
{"components not a map", "components: warn\n", "log.components"},
|
||||
{"channels not a map", "channels: console\n", "log.channels"},
|
||||
}
|
||||
for _, tc := range cases {
|
||||
t.Run(tc.name, func(t *testing.T) {
|
||||
_, err := diary.ParseConfig(openYAMLConfig(t, tc.yaml))
|
||||
if err == nil {
|
||||
t.Fatalf("ParseConfig accepted:\n%s", tc.yaml)
|
||||
}
|
||||
if !strings.Contains(err.Error(), tc.key) {
|
||||
t.Errorf("error %q does not name %s", err, tc.key)
|
||||
}
|
||||
})
|
||||
}
|
||||
|
||||
// A cycle error names the path it found.
|
||||
_, err := diary.ParseConfig(openYAMLConfig(t, cases[19].yaml))
|
||||
if err == nil || !strings.Contains(err.Error(), "a -> b -> a") {
|
||||
t.Errorf("cycle error = %v, want the path a -> b -> a", err)
|
||||
}
|
||||
|
||||
// A YAML list, a comma string in YAML and a comma string from the
|
||||
// environment give the same stack.
|
||||
list, err := diary.ParseConfig(openYAMLConfig(t, "channels:\n stack:\n channels: [console, daily]\n"))
|
||||
if err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
comma, err := diary.ParseConfig(openYAMLConfig(t, "channels:\n stack:\n channels: \" console , daily \"\n"))
|
||||
if err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
env, err := diary.ParseConfig(openConfig(t, "SUMMER_LOG__CHANNELS__STACK__CHANNELS=console,daily"))
|
||||
if err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
if !reflect.DeepEqual(list, comma) || !reflect.DeepEqual(list, env) {
|
||||
t.Errorf("list, comma and env stacks differ:\n list %+v\ncomma %+v\n env %+v", list.Channels["stack"], comma.Channels["stack"], env.Channels["stack"])
|
||||
}
|
||||
|
||||
// Levels accept warning as warn and any case; days 0 keeps every file.
|
||||
got, err := diary.ParseConfig(openYAMLConfig(t, "level: WARNING\nchannels:\n daily:\n days: 0\n"))
|
||||
if err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
if got.Level != slog.LevelWarn || got.Channels["daily"].Days != 0 {
|
||||
t.Errorf("level %v days %d, want WARN and 0", got.Level, got.Channels["daily"].Days)
|
||||
}
|
||||
|
||||
// compass keeps a dotted YAML key literal, so it does not nest; only
|
||||
// the nested form (above, or from SUMMER_LOG__ variables) is refused.
|
||||
got, err = diary.ParseConfig(openYAMLConfig(t, "components:\n golem15.blog: debug\n"))
|
||||
if err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
if got.Components["golem15.blog"] != slog.LevelDebug {
|
||||
t.Errorf("literal dotted component = %v", got.Components)
|
||||
}
|
||||
}
|
||||
|
||||
// TestConfigEnvStrings: SUMMER_LOG__ overrides arrive as strings and
|
||||
// overlay the defaults key by key, also on top of config/log.yaml.
|
||||
func TestConfigEnvStrings(t *testing.T) {
|
||||
got, err := diary.ParseConfig(openConfig(t,
|
||||
"SUMMER_LOG__LEVEL=debug",
|
||||
"SUMMER_LOG__CHANNELS__DAILY__LEVEL=error",
|
||||
"SUMMER_LOG__CHANNELS__DAILY__DAYS=7",
|
||||
"SUMMER_LOG__COMPONENTS__JOURNAL=debug",
|
||||
))
|
||||
if err != nil {
|
||||
t.Fatalf("ParseConfig: %v", err)
|
||||
}
|
||||
want := diary.DefaultConfig()
|
||||
want.Level = slog.LevelDebug
|
||||
daily := want.Channels["daily"]
|
||||
daily.Level, daily.HasLevel, daily.Days = slog.LevelError, true, 7
|
||||
want.Channels["daily"] = daily
|
||||
want.Components["journal"] = slog.LevelDebug
|
||||
if !reflect.DeepEqual(got, want) {
|
||||
t.Errorf("env overlay:\n got %+v\nwant %+v", got, want)
|
||||
}
|
||||
|
||||
// The environment wins over the file, and keys the environment does
|
||||
// not set keep the file's values.
|
||||
got, err = diary.ParseConfig(openYAMLConfig(t,
|
||||
"channels:\n daily:\n path: var/log/app.log\n days: 3\n",
|
||||
"SUMMER_LOG__CHANNELS__DAILY__DAYS=9",
|
||||
))
|
||||
if err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
if d := got.Channels["daily"]; d.Path != "var/log/app.log" || d.Days != 9 || d.Format != diary.FormatJSON || d.Level != slog.LevelWarn {
|
||||
t.Errorf("daily channel = %+v, want path var/log/app.log, days 9 and the default format and level", d)
|
||||
}
|
||||
|
||||
// A nil config gives the defaults.
|
||||
none, err := diary.ParseConfig(nil)
|
||||
if err != nil || !reflect.DeepEqual(none, diary.DefaultConfig()) {
|
||||
t.Errorf("ParseConfig(nil) = %+v, %v; want the defaults", none, err)
|
||||
}
|
||||
}
|
||||
|
||||
// TestDefaultConfig: the defaults equal the D-08 example (components river
|
||||
// warn), and the config/log.yaml that summer new writes parses to the
|
||||
// defaults plus its http component.
|
||||
func TestDefaultConfig(t *testing.T) {
|
||||
example := `default: stack
|
||||
level: info
|
||||
channels:
|
||||
stack:
|
||||
driver: stack
|
||||
channels: [console, daily]
|
||||
console:
|
||||
driver: console
|
||||
format: auto
|
||||
daily:
|
||||
driver: daily
|
||||
path: storage/logs/summer.log
|
||||
days: 14
|
||||
format: json
|
||||
level: warn
|
||||
components:
|
||||
river: warn
|
||||
`
|
||||
got, err := diary.ParseConfig(openYAMLConfig(t, example))
|
||||
if err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
if !reflect.DeepEqual(got, diary.DefaultConfig()) {
|
||||
t.Errorf("D-08 example:\n got %+v\nwant %+v", got, diary.DefaultConfig())
|
||||
}
|
||||
def := diary.DefaultConfig()
|
||||
if def.Default != "stack" || def.Level != slog.LevelInfo || def.Components["river"] != slog.LevelWarn || len(def.Components) != 1 {
|
||||
t.Errorf("DefaultConfig head = %q %v %v", def.Default, def.Level, def.Components)
|
||||
}
|
||||
for _, name := range []string{"stack", "console", "daily", "stderr", "null"} {
|
||||
if _, ok := def.Channels[name]; !ok {
|
||||
t.Errorf("DefaultConfig lacks channel %q", name)
|
||||
}
|
||||
}
|
||||
// The defaults are a fresh copy each time.
|
||||
def.Components["river"] = slog.LevelDebug
|
||||
if diary.DefaultConfig().Components["river"] != slog.LevelWarn {
|
||||
t.Error("DefaultConfig returns shared maps")
|
||||
}
|
||||
|
||||
generated, err := os.ReadFile(filepath.Join("..", "..", "internal", "build", "testdata", "new", "config__log.yaml.golden"))
|
||||
if err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
got, err = diary.ParseConfig(openYAMLConfig(t, string(generated)))
|
||||
if err != nil {
|
||||
t.Fatalf("generated config/log.yaml: %v", err)
|
||||
}
|
||||
want := diary.DefaultConfig()
|
||||
want.Components["http"] = slog.LevelInfo
|
||||
if !reflect.DeepEqual(got, want) {
|
||||
t.Errorf("generated config/log.yaml:\n got %+v\nwant %+v", got, want)
|
||||
}
|
||||
}
|
||||
159
modules/diary/console_test.go
Normal file
159
modules/diary/console_test.go
Normal file
@@ -0,0 +1,159 @@
|
||||
package diary_test
|
||||
|
||||
import (
|
||||
"bytes"
|
||||
"context"
|
||||
"log/slog"
|
||||
"strings"
|
||||
"testing"
|
||||
"time"
|
||||
|
||||
"git.golem15.com/golem15/summercms/modules/bonfire"
|
||||
"git.golem15.com/golem15/summercms/modules/diary"
|
||||
"github.com/charmbracelet/colorprofile"
|
||||
)
|
||||
|
||||
// record handles one record with a zero time (no time column) on h.
|
||||
func record(t *testing.T, h slog.Handler, level slog.Level, msg string, attrs ...slog.Attr) {
|
||||
t.Helper()
|
||||
r := slog.NewRecord(time.Time{}, level, msg, 0)
|
||||
r.AddAttrs(attrs...)
|
||||
if err := h.Handle(context.Background(), r); err != nil {
|
||||
t.Fatalf("Handle: %v", err)
|
||||
}
|
||||
}
|
||||
|
||||
// TestConsoleStripsControlChars: control characters in the message, in
|
||||
// attribute keys and in values never reach the terminal; line breaks become
|
||||
// spaces, so one record is one line.
|
||||
func TestConsoleStripsControlChars(t *testing.T) {
|
||||
for _, profile := range []colorprofile.Profile{colorprofile.NoTTY, colorprofile.ANSI256} {
|
||||
var buf bytes.Buffer
|
||||
h := diary.NewConsoleHandler(&buf, diary.ConsoleOptions{Profile: profile})
|
||||
record(t, h, slog.LevelInfo, "evil \x1b[31mred\x1b[0m\a bell\nsecond line\rreturn",
|
||||
slog.String("value", "a\x1b]0;title\x07b\nc"),
|
||||
slog.String("k\x1bey", "v"),
|
||||
slog.Any("err", errString("boom\x1b[2Jclear")))
|
||||
out := buf.String()
|
||||
if strings.Count(out, "\n") != 1 || !strings.HasSuffix(out, "\n") {
|
||||
t.Errorf("profile %v: record is not exactly one line: %q", profile, out)
|
||||
}
|
||||
for _, bad := range []string{"\x1b[31mred", "\x1b]0;", "\a", "\x07", "\r", "\x1b[2J", "k\x1bey"} {
|
||||
if strings.Contains(out, bad) {
|
||||
t.Errorf("profile %v: output carries %q: %q", profile, bad, out)
|
||||
}
|
||||
}
|
||||
for _, want := range []string{"[31mred", "bell second line return", "[2Jclear", "key="} {
|
||||
if !strings.Contains(out, want) {
|
||||
t.Errorf("profile %v: output lacks the cleaned text %q: %q", profile, want, out)
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
type errString string
|
||||
|
||||
func (e errString) Error() string { return string(e) }
|
||||
|
||||
// TestConsoleComponentPrefix: the component is a fixed-width column, so
|
||||
// messages line up whether a record has a short component, none or one
|
||||
// given as a record attribute; inside a group it is an ordinary attribute.
|
||||
func TestConsoleComponentPrefix(t *testing.T) {
|
||||
var buf bytes.Buffer
|
||||
h := diary.NewConsoleHandler(&buf, diary.ConsoleOptions{Profile: colorprofile.NoTTY})
|
||||
record(t, h.WithAttrs([]slog.Attr{slog.String(diary.ComponentKey, "db")}), slog.LevelInfo, "MSG")
|
||||
record(t, h.WithAttrs([]slog.Attr{slog.String(diary.ComponentKey, "journal")}), slog.LevelWarn, "MSG")
|
||||
record(t, h, slog.LevelError, "MSG")
|
||||
record(t, h, slog.LevelDebug, "MSG", slog.String(diary.ComponentKey, "river"))
|
||||
record(t, h.WithGroup("g").WithAttrs([]slog.Attr{slog.String(diary.ComponentKey, "inner")}), slog.LevelInfo, "MSG")
|
||||
|
||||
lines := strings.Split(strings.TrimSuffix(buf.String(), "\n"), "\n")
|
||||
if len(lines) != 5 {
|
||||
t.Fatalf("got %d lines, want 5:\n%s", len(lines), buf.String())
|
||||
}
|
||||
wantPrefix := []string{
|
||||
"INFO db MSG",
|
||||
"WARN journal MSG",
|
||||
"ERROR MSG",
|
||||
"DEBUG river MSG",
|
||||
"INFO MSG g.component=inner",
|
||||
}
|
||||
for i, want := range wantPrefix {
|
||||
if !strings.HasPrefix(lines[i], want) {
|
||||
t.Errorf("line %d = %q, want prefix %q", i, lines[i], want)
|
||||
}
|
||||
if col := strings.Index(lines[i], "MSG"); col != 17 {
|
||||
t.Errorf("line %d: message at column %d, want 17: %q", i, col, lines[i])
|
||||
}
|
||||
}
|
||||
if strings.Contains(lines[3], "component=") {
|
||||
t.Errorf("record-level component printed as an attribute: %q", lines[3])
|
||||
}
|
||||
|
||||
// A record with a time starts with HH:MM:SS.
|
||||
buf.Reset()
|
||||
r := slog.NewRecord(time.Date(2026, 10, 21, 9, 5, 7, 0, time.Local), slog.LevelInfo, "timed", 0)
|
||||
if err := h.Handle(context.Background(), r); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
if !strings.HasPrefix(buf.String(), "09:05:07 INFO ") {
|
||||
t.Errorf("timed line = %q, want the 09:05:07 prefix", buf.String())
|
||||
}
|
||||
}
|
||||
|
||||
// TestConsoleStyledOnlyOnTerminal: the NoTTY profile writes no escape
|
||||
// codes and ANSI256 does; through Setup, the auto format styles only when
|
||||
// the profile allows it (never on a plain buffer unless forced).
|
||||
func TestConsoleStyledOnlyOnTerminal(t *testing.T) {
|
||||
for _, tc := range []struct {
|
||||
profile colorprofile.Profile
|
||||
styled bool
|
||||
}{{colorprofile.NoTTY, false}, {colorprofile.ANSI256, true}, {colorprofile.TrueColor, true}} {
|
||||
var buf bytes.Buffer
|
||||
h := diary.NewConsoleHandler(&buf, diary.ConsoleOptions{Profile: tc.profile})
|
||||
record(t, h.WithAttrs([]slog.Attr{slog.String(diary.ComponentKey, "blog")}), slog.LevelWarn, "styled?", slog.Int("n", 1))
|
||||
if got := strings.Contains(buf.String(), "\x1b["); got != tc.styled {
|
||||
t.Errorf("profile %v: escape codes %v, want %v: %q", tc.profile, got, tc.styled, buf.String())
|
||||
}
|
||||
}
|
||||
|
||||
for _, tc := range []struct {
|
||||
name string
|
||||
color bonfire.ColorMode
|
||||
environ []string
|
||||
styled bool
|
||||
}{
|
||||
{"auto on a buffer", bonfire.ColorAuto, []string{}, false},
|
||||
{"auto forced", bonfire.ColorAuto, []string{"FORCE_COLOR=1"}, true},
|
||||
{"auto forced but NO_COLOR", bonfire.ColorAuto, []string{"FORCE_COLOR=1", "NO_COLOR=1"}, false},
|
||||
{"always", bonfire.ColorAlways, []string{}, true},
|
||||
{"never forced", bonfire.ColorNever, []string{"FORCE_COLOR=1"}, false},
|
||||
} {
|
||||
t.Run(tc.name, func(t *testing.T) {
|
||||
var buf lockedBuffer
|
||||
setup(t, diary.Options{Stderr: &buf, Color: tc.color, Environ: tc.environ}, "SUMMER_LOG__DEFAULT=console")
|
||||
diary.For("blog").Info("hello")
|
||||
out := buf.String()
|
||||
if got := strings.Contains(out, "\x1b["); got != tc.styled {
|
||||
t.Errorf("escape codes %v, want %v: %q", got, tc.styled, out)
|
||||
}
|
||||
if !tc.styled && !strings.Contains(out, "level=INFO") {
|
||||
t.Errorf("unstyled console is not logfmt: %q", out)
|
||||
}
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
// TestConsoleLevelFromOptions: ConsoleOptions.Level gates records and nil
|
||||
// means info.
|
||||
func TestConsoleLevelFromOptions(t *testing.T) {
|
||||
var buf bytes.Buffer
|
||||
h := diary.NewConsoleHandler(&buf, diary.ConsoleOptions{Profile: colorprofile.NoTTY})
|
||||
if h.Enabled(context.Background(), slog.LevelDebug) || !h.Enabled(context.Background(), slog.LevelInfo) {
|
||||
t.Error("default console level is not info")
|
||||
}
|
||||
h = diary.NewConsoleHandler(&buf, diary.ConsoleOptions{Profile: colorprofile.NoTTY, Level: slog.LevelError})
|
||||
if h.Enabled(context.Background(), slog.LevelWarn) {
|
||||
t.Error("console level error lets warn through")
|
||||
}
|
||||
}
|
||||
270
modules/diary/daily_test.go
Normal file
270
modules/diary/daily_test.go
Normal file
@@ -0,0 +1,270 @@
|
||||
//go:build unix
|
||||
|
||||
package diary_test
|
||||
|
||||
import (
|
||||
"os"
|
||||
"path/filepath"
|
||||
"slices"
|
||||
"strings"
|
||||
"syscall"
|
||||
"testing"
|
||||
|
||||
"git.golem15.com/golem15/summercms/modules/diary"
|
||||
)
|
||||
|
||||
// dailyOnly is the environment of a configuration whose default channel is
|
||||
// the daily file at info.
|
||||
var dailyOnly = []string{"SUMMER_LOG__DEFAULT=daily", "SUMMER_LOG__CHANNELS__DAILY__LEVEL=info"}
|
||||
|
||||
// TestDailyRotation: a record before and one after local midnight land in
|
||||
// two files named by their dates.
|
||||
func TestDailyRotation(t *testing.T) {
|
||||
root := t.TempDir()
|
||||
clk := newClock(day(21, 23, 59, 59))
|
||||
var buf lockedBuffer
|
||||
setup(t, diary.Options{Stderr: &buf, Root: root, Now: clk.Now}, dailyOnly...)
|
||||
blog := diary.For("blog")
|
||||
|
||||
blog.Info("before midnight")
|
||||
clk.Set(day(22, 0, 0, 1))
|
||||
blog.Info("after midnight")
|
||||
|
||||
dir := filepath.Join(root, "storage", "logs")
|
||||
first := readDaily(t, filepath.Join(dir, "summer-2026-10-21.log"))
|
||||
second := readDaily(t, filepath.Join(dir, "summer-2026-10-22.log"))
|
||||
if len(first) != 1 || !strings.Contains(first[0], "before midnight") {
|
||||
t.Errorf("2026-10-21 file = %q, want only the record before midnight", first)
|
||||
}
|
||||
if len(second) != 1 || !strings.Contains(second[0], "after midnight") {
|
||||
t.Errorf("2026-10-22 file = %q, want only the record after midnight", second)
|
||||
}
|
||||
if buf.String() != "" {
|
||||
t.Errorf("console written although the default channel is daily:\n%s", buf.String())
|
||||
}
|
||||
}
|
||||
|
||||
// TestDailyRetention: with days 2 the files of today and the day before are
|
||||
// kept, older files of the same base are deleted, and every other file in
|
||||
// the directory is left alone. days 0 keeps everything.
|
||||
func TestDailyRetention(t *testing.T) {
|
||||
keep := []string{
|
||||
"summer-2026-10-20.log", "summer-2026-10-21.log",
|
||||
"summer.log", "other-2026-10-01.log", "summer-2026-10-01.json",
|
||||
"summer-latest.log", "summer-2026-1-1.log", "notes.txt", "xsummer-2026-10-01.log",
|
||||
}
|
||||
gone := []string{"summer-2026-10-19.log", "summer-2026-10-18.log", "summer-2025-01-01.log"}
|
||||
|
||||
prepare := func(t *testing.T) string {
|
||||
t.Helper()
|
||||
root := t.TempDir()
|
||||
dir := filepath.Join(root, "storage", "logs")
|
||||
if err := os.MkdirAll(filepath.Join(dir, "summer-2026-10-01.log"), 0o750); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
for _, name := range append(slices.Clone(keep), gone...) {
|
||||
if err := os.WriteFile(filepath.Join(dir, name), []byte("old\n"), 0o640); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
}
|
||||
return root
|
||||
}
|
||||
list := func(t *testing.T, root string) []string {
|
||||
t.Helper()
|
||||
entries, err := os.ReadDir(filepath.Join(root, "storage", "logs"))
|
||||
if err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
var names []string
|
||||
for _, e := range entries {
|
||||
names = append(names, e.Name())
|
||||
}
|
||||
return names
|
||||
}
|
||||
|
||||
root := prepare(t)
|
||||
setup(t, diary.Options{Root: root, Stderr: &lockedBuffer{}},
|
||||
append(slices.Clone(dailyOnly), "SUMMER_LOG__CHANNELS__DAILY__DAYS=2")...)
|
||||
diary.For("blog").Info("today")
|
||||
names := list(t, root)
|
||||
for _, name := range append(slices.Clone(keep), "summer-2026-10-01.log") {
|
||||
if !slices.Contains(names, name) {
|
||||
t.Errorf("retention deleted %s; left %v", name, names)
|
||||
}
|
||||
}
|
||||
for _, name := range gone {
|
||||
if slices.Contains(names, name) {
|
||||
t.Errorf("retention kept %s; left %v", name, names)
|
||||
}
|
||||
}
|
||||
today := readDaily(t, filepath.Join(root, "storage", "logs", "summer-2026-10-21.log"))
|
||||
if len(today) != 2 || today[0] != "old" || !strings.Contains(today[1], `"msg":"today"`) {
|
||||
t.Errorf("today's file = %q, want the old line and the new record appended", today)
|
||||
}
|
||||
|
||||
diary.Reset()
|
||||
root = prepare(t)
|
||||
setup(t, diary.Options{Root: root, Stderr: &lockedBuffer{}},
|
||||
append(slices.Clone(dailyOnly), "SUMMER_LOG__CHANNELS__DAILY__DAYS=0")...)
|
||||
diary.For("blog").Info("today")
|
||||
names = list(t, root)
|
||||
for _, name := range append(slices.Clone(keep), gone...) {
|
||||
if !slices.Contains(names, name) {
|
||||
t.Errorf("days 0 deleted %s", name)
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// TestDailyPermissions: a new daily file is 0640 whatever the umask, its
|
||||
// directory 0750 under the usual umask, and an existing file keeps its mode.
|
||||
func TestDailyPermissions(t *testing.T) {
|
||||
old := syscall.Umask(0o022)
|
||||
t.Cleanup(func() { syscall.Umask(old) })
|
||||
|
||||
root := t.TempDir()
|
||||
setup(t, diary.Options{Root: root, Stderr: &lockedBuffer{}}, dailyOnly...)
|
||||
diary.For("blog").Info("first")
|
||||
dir := filepath.Join(root, "storage", "logs")
|
||||
file := filepath.Join(dir, "summer-2026-10-21.log")
|
||||
readDaily(t, file)
|
||||
assertMode(t, file, 0o640)
|
||||
assertMode(t, dir, 0o750)
|
||||
|
||||
// A strict umask cannot strip the file's group read bit.
|
||||
diary.Reset()
|
||||
syscall.Umask(0o077)
|
||||
root = t.TempDir()
|
||||
setup(t, diary.Options{Root: root, Stderr: &lockedBuffer{}}, dailyOnly...)
|
||||
diary.For("blog").Info("strict umask")
|
||||
file = filepath.Join(root, "storage", "logs", "summer-2026-10-21.log")
|
||||
readDaily(t, file)
|
||||
assertMode(t, file, 0o640)
|
||||
|
||||
// An existing file is appended to and keeps its mode.
|
||||
diary.Reset()
|
||||
syscall.Umask(0o022)
|
||||
root = t.TempDir()
|
||||
dir = filepath.Join(root, "storage", "logs")
|
||||
if err := os.MkdirAll(dir, 0o750); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
file = filepath.Join(dir, "summer-2026-10-21.log")
|
||||
if err := os.WriteFile(file, nil, 0o600); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
setup(t, diary.Options{Root: root, Stderr: &lockedBuffer{}}, dailyOnly...)
|
||||
diary.For("blog").Info("existing")
|
||||
if lines := readDaily(t, file); len(lines) != 1 {
|
||||
t.Errorf("existing file has %d lines, want 1", len(lines))
|
||||
}
|
||||
assertMode(t, file, 0o600)
|
||||
}
|
||||
|
||||
func assertMode(t *testing.T, path string, want os.FileMode) {
|
||||
t.Helper()
|
||||
info, err := os.Stat(path)
|
||||
if err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
if got := info.Mode().Perm(); got != want {
|
||||
t.Errorf("%s mode = %o, want %o", path, got, want)
|
||||
}
|
||||
}
|
||||
|
||||
// TestDailyUnwritable: a daily file that cannot be opened warns once (on a
|
||||
// plain stderr handler when no console channel exists), never fails Setup,
|
||||
// and later records are dropped silently.
|
||||
func TestDailyUnwritable(t *testing.T) {
|
||||
root := t.TempDir()
|
||||
// A regular file where the log directory should be: MkdirAll fails for
|
||||
// every user, root included.
|
||||
if err := os.WriteFile(filepath.Join(root, "blocker"), []byte("x"), 0o600); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
var buf lockedBuffer
|
||||
setup(t, diary.Options{Root: root, Stderr: &buf},
|
||||
append(slices.Clone(dailyOnly), "SUMMER_LOG__CHANNELS__DAILY__PATH=blocker/logs/summer.log")...)
|
||||
blog := diary.For("blog")
|
||||
for i := range 5 {
|
||||
blog.Info("record", "i", i)
|
||||
}
|
||||
out := buf.String()
|
||||
if n := strings.Count(out, "daily log file disabled"); n != 1 {
|
||||
t.Fatalf("warning appears %d times, want 1:\n%s", n, out)
|
||||
}
|
||||
for _, want := range []string{"level=WARN", "component=diary", filepath.Join(root, "blocker", "logs", "summer-2026-10-21.log")} {
|
||||
if !strings.Contains(out, want) {
|
||||
t.Errorf("warning lacks %q:\n%s", want, out)
|
||||
}
|
||||
}
|
||||
if strings.Contains(out, "msg=record") {
|
||||
t.Errorf("records reached stderr although the default channel is daily:\n%s", out)
|
||||
}
|
||||
if err := diary.Close(); err != nil {
|
||||
t.Errorf("Close after a disabled daily file: %v", err)
|
||||
}
|
||||
}
|
||||
|
||||
// TestDailyLazyOpen: no file or directory exists until a record reaches the
|
||||
// daily channel; a closed file opens again on the next record.
|
||||
func TestDailyLazyOpen(t *testing.T) {
|
||||
root := t.TempDir()
|
||||
var buf lockedBuffer
|
||||
setup(t, diary.Options{Root: root, Stderr: &buf})
|
||||
storage := filepath.Join(root, "storage")
|
||||
if _, err := os.Stat(storage); !os.IsNotExist(err) {
|
||||
t.Fatalf("Setup created %s (err %v)", storage, err)
|
||||
}
|
||||
diary.For("blog").Info("below the daily level")
|
||||
if _, err := os.Stat(storage); !os.IsNotExist(err) {
|
||||
t.Fatalf("an info record created %s although the daily level is warn (err %v)", storage, err)
|
||||
}
|
||||
if !strings.Contains(buf.String(), "below the daily level") {
|
||||
t.Errorf("console lacks the info record:\n%s", buf.String())
|
||||
}
|
||||
|
||||
file := filepath.Join(storage, "logs", "summer-2026-10-21.log")
|
||||
diary.For("blog").Warn("first warning")
|
||||
if lines := readDaily(t, file); len(lines) != 1 {
|
||||
t.Fatalf("daily file has %d lines after one warning, want 1", len(lines))
|
||||
}
|
||||
diary.For("blog").Warn("after close")
|
||||
if lines := readDaily(t, file); len(lines) != 2 {
|
||||
t.Fatalf("daily file has %d lines after reopening, want 2", len(lines))
|
||||
}
|
||||
}
|
||||
|
||||
// TestPathConfinement: a relative daily path may not leave the application
|
||||
// root; a path that stays inside after cleaning and an absolute path are
|
||||
// accepted, and relative paths resolve against Options.Root.
|
||||
func TestPathConfinement(t *testing.T) {
|
||||
for _, path := range []string{"../summer.log", "storage/../../summer.log", "./../logs/summer.log", ".."} {
|
||||
_, err := diary.ParseConfig(openConfig(t, "SUMMER_LOG__CHANNELS__DAILY__PATH="+path))
|
||||
if err == nil || !strings.Contains(err.Error(), "log.channels.daily.path") {
|
||||
t.Errorf("path %q: err %v, want an error naming log.channels.daily.path", path, err)
|
||||
}
|
||||
}
|
||||
|
||||
abs := filepath.Join(t.TempDir(), "elsewhere", "app.log")
|
||||
for _, path := range []string{"storage/../logs/summer.log", "logs/app.log", abs} {
|
||||
if _, err := diary.ParseConfig(openConfig(t, "SUMMER_LOG__CHANNELS__DAILY__PATH="+path)); err != nil {
|
||||
t.Errorf("path %q rejected: %v", path, err)
|
||||
}
|
||||
}
|
||||
|
||||
root := t.TempDir()
|
||||
setup(t, diary.Options{Root: root, Stderr: &lockedBuffer{}},
|
||||
append(slices.Clone(dailyOnly), "SUMMER_LOG__CHANNELS__DAILY__PATH="+abs)...)
|
||||
diary.For("blog").Info("absolute")
|
||||
if lines := readDaily(t, filepath.Join(filepath.Dir(abs), "app-2026-10-21.log")); len(lines) != 1 {
|
||||
t.Errorf("absolute path file has %d lines, want 1", len(lines))
|
||||
}
|
||||
|
||||
diary.Reset()
|
||||
setup(t, diary.Options{Root: root, Stderr: &lockedBuffer{}},
|
||||
append(slices.Clone(dailyOnly), "SUMMER_LOG__CHANNELS__DAILY__PATH=storage/../logs/app.log")...)
|
||||
diary.For("blog").Info("relative")
|
||||
if lines := readDaily(t, filepath.Join(root, "logs", "app-2026-10-21.log")); len(lines) != 1 {
|
||||
t.Errorf("relative path did not resolve against the root: %d lines", len(lines))
|
||||
}
|
||||
}
|
||||
535
modules/diary/diary_test.go
Normal file
535
modules/diary/diary_test.go
Normal file
@@ -0,0 +1,535 @@
|
||||
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
|
||||
}
|
||||
159
modules/diary/slogtest_test.go
Normal file
159
modules/diary/slogtest_test.go
Normal file
@@ -0,0 +1,159 @@
|
||||
package diary_test
|
||||
|
||||
import (
|
||||
"bytes"
|
||||
"encoding/json"
|
||||
"fmt"
|
||||
"log/slog"
|
||||
"regexp"
|
||||
"strconv"
|
||||
"strings"
|
||||
"testing"
|
||||
"testing/slogtest"
|
||||
|
||||
"git.golem15.com/golem15/summercms/modules/diary"
|
||||
"github.com/charmbracelet/colorprofile"
|
||||
)
|
||||
|
||||
// TestSlogtestConsoleHandler: the styled console handler (with the NoTTY
|
||||
// profile, so its lines carry no escape codes) passes testing/slogtest.
|
||||
func TestSlogtestConsoleHandler(t *testing.T) {
|
||||
var buf bytes.Buffer
|
||||
h := diary.NewConsoleHandler(&buf, diary.ConsoleOptions{Profile: colorprofile.NoTTY})
|
||||
results := func() []map[string]any {
|
||||
var out []map[string]any
|
||||
for _, line := range strings.Split(strings.TrimSuffix(buf.String(), "\n"), "\n") {
|
||||
if line == "" {
|
||||
continue
|
||||
}
|
||||
m, err := parseConsoleLine(line)
|
||||
if err != nil {
|
||||
t.Fatalf("unparsable console line %q: %v", line, err)
|
||||
}
|
||||
out = append(out, m)
|
||||
}
|
||||
return out
|
||||
}
|
||||
if err := slogtest.TestHandler(h, results); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
}
|
||||
|
||||
// TestSlogtestPipeline: the full pipeline (component handler, sunscreen and
|
||||
// a stack of a JSON stderr channel and a null channel) passes
|
||||
// testing/slogtest through its JSON output, for a component logger and for
|
||||
// the process default.
|
||||
func TestSlogtestPipeline(t *testing.T) {
|
||||
for _, name := range []string{"pipeline", ""} {
|
||||
t.Run(fmt.Sprintf("component %q", name), func(t *testing.T) {
|
||||
var buf lockedBuffer
|
||||
setup(t, diary.Options{Stderr: &buf},
|
||||
"SUMMER_LOG__DEFAULT=stack",
|
||||
"SUMMER_LOG__CHANNELS__STACK__CHANNELS=stderr,null",
|
||||
"SUMMER_LOG__CHANNELS__STDERR__FORMAT=json",
|
||||
)
|
||||
h := diary.For(name).Handler()
|
||||
if name == "" {
|
||||
h = slog.Default().Handler()
|
||||
}
|
||||
results := func() []map[string]any {
|
||||
var out []map[string]any
|
||||
for _, line := range strings.Split(strings.TrimSpace(buf.String()), "\n") {
|
||||
var m map[string]any
|
||||
if err := json.Unmarshal([]byte(line), &m); err != nil {
|
||||
t.Fatalf("pipeline line is not JSON: %q: %v", line, err)
|
||||
}
|
||||
if name != "" && m[diary.ComponentKey] != name {
|
||||
t.Fatalf("pipeline record lacks component %q: %v", name, m)
|
||||
}
|
||||
out = append(out, m)
|
||||
}
|
||||
return out
|
||||
}
|
||||
if err := slogtest.TestHandler(h, results); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
var consoleTime = regexp.MustCompile(`^\d{2}:\d{2}:\d{2} `)
|
||||
|
||||
// parseConsoleLine reads one console line without a component: an optional
|
||||
// HH:MM:SS time, the level, the message (the words before the first
|
||||
// key=value field) and key=value fields whose dotted keys become nested
|
||||
// maps. Quoted values are unquoted.
|
||||
func parseConsoleLine(line string) (map[string]any, error) {
|
||||
m := map[string]any{}
|
||||
if loc := consoleTime.FindStringIndex(line); loc != nil {
|
||||
m[slog.TimeKey] = strings.TrimSpace(line[:loc[1]])
|
||||
line = line[loc[1]:]
|
||||
}
|
||||
level, rest, ok := strings.Cut(line, " ")
|
||||
if !ok {
|
||||
return nil, fmt.Errorf("no level")
|
||||
}
|
||||
m[slog.LevelKey] = level
|
||||
tokens, err := splitFields(strings.TrimLeft(rest, " "))
|
||||
if err != nil {
|
||||
return nil, err
|
||||
}
|
||||
var msg []string
|
||||
i := 0
|
||||
for ; i < len(tokens) && !strings.Contains(tokens[i], "="); i++ {
|
||||
msg = append(msg, tokens[i])
|
||||
}
|
||||
m[slog.MessageKey] = strings.Join(msg, " ")
|
||||
for ; i < len(tokens); i++ {
|
||||
key, raw, _ := strings.Cut(tokens[i], "=")
|
||||
value := raw
|
||||
if strings.HasPrefix(raw, `"`) {
|
||||
if value, err = strconv.Unquote(raw); err != nil {
|
||||
return nil, fmt.Errorf("value of %s: %w", key, err)
|
||||
}
|
||||
}
|
||||
parts := strings.Split(key, ".")
|
||||
cur := m
|
||||
for _, p := range parts[:len(parts)-1] {
|
||||
next, ok := cur[p].(map[string]any)
|
||||
if !ok {
|
||||
next = map[string]any{}
|
||||
cur[p] = next
|
||||
}
|
||||
cur = next
|
||||
}
|
||||
cur[parts[len(parts)-1]] = value
|
||||
}
|
||||
return m, nil
|
||||
}
|
||||
|
||||
// splitFields splits s on spaces, keeping a double-quoted value (with
|
||||
// backslash escapes) inside its field.
|
||||
func splitFields(s string) ([]string, error) {
|
||||
var out []string
|
||||
for s != "" {
|
||||
var b strings.Builder
|
||||
for s != "" && s[0] != ' ' {
|
||||
if s[0] == '"' {
|
||||
end := 1
|
||||
for end < len(s) && s[end] != '"' {
|
||||
if s[end] == '\\' {
|
||||
end++
|
||||
}
|
||||
end++
|
||||
}
|
||||
if end >= len(s) {
|
||||
return nil, fmt.Errorf("unterminated quote")
|
||||
}
|
||||
b.WriteString(s[:end+1])
|
||||
s = s[end+1:]
|
||||
continue
|
||||
}
|
||||
b.WriteByte(s[0])
|
||||
s = s[1:]
|
||||
}
|
||||
out = append(out, b.String())
|
||||
s = strings.TrimLeft(s, " ")
|
||||
}
|
||||
return out, nil
|
||||
}
|
||||
Reference in New Issue
Block a user