diff --git a/modules/diary/config_test.go b/modules/diary/config_test.go new file mode 100644 index 00000000..9501a2ca --- /dev/null +++ b/modules/diary/config_test.go @@ -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) + } +} diff --git a/modules/diary/console_test.go b/modules/diary/console_test.go new file mode 100644 index 00000000..14c30b65 --- /dev/null +++ b/modules/diary/console_test.go @@ -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") + } +} diff --git a/modules/diary/daily_test.go b/modules/diary/daily_test.go new file mode 100644 index 00000000..152c7565 --- /dev/null +++ b/modules/diary/daily_test.go @@ -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)) + } +} diff --git a/modules/diary/diary_test.go b/modules/diary/diary_test.go new file mode 100644 index 00000000..b83c2f9e --- /dev/null +++ b/modules/diary/diary_test.go @@ -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- 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 +} diff --git a/modules/diary/slogtest_test.go b/modules/diary/slogtest_test.go new file mode 100644 index 00000000..9543fd44 --- /dev/null +++ b/modules/diary/slogtest_test.go @@ -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 +} diff --git a/modules/sunscreen/sunscreen_test.go b/modules/sunscreen/sunscreen_test.go index 62b74609..2155cc7c 100644 --- a/modules/sunscreen/sunscreen_test.go +++ b/modules/sunscreen/sunscreen_test.go @@ -142,3 +142,42 @@ func TestInstallDefault(t *testing.T) { t.Fatalf("default logger output:\n%s", out) } } + +// TestInstallDefaultUnchanged: InstallDefault, the compatibility entry +// point that generated applications no longer call, still installs a +// redacting logfmt TextHandler on the given writer, and each call replaces +// the previous default instead of wrapping it. +func TestInstallDefaultUnchanged(t *testing.T) { + prev := slog.Default() + prevFlags, prevWriter := log.Flags(), log.Writer() + t.Cleanup(func() { + slog.SetDefault(prev) + log.SetFlags(prevFlags) + log.SetOutput(prevWriter) + }) + var first, second bytes.Buffer + InstallDefault(&first) + InstallDefault(&second) + slog.Debug("below the default level", "token", nested) + slog.Info("payment for Bearer "+bearer, "api_key", apiKey, slog.Group("g", "Password", passwd)) + if first.Len() != 0 { + t.Fatalf("the replaced default still receives records:\n%s", first.String()) + } + out := second.String() + if strings.Count(out, "\n") != 1 { + t.Fatalf("want exactly one line (info level, debug dropped):\n%s", out) + } + for _, want := range []string{"time=", " level=INFO ", `msg="payment for Bearer [REDACTED]"`, "api_key=[REDACTED]", "g.Password=[REDACTED]"} { + if !strings.Contains(out, want) { + t.Errorf("default output lacks %q:\n%s", want, out) + } + } + for _, secret := range []string{bearer, apiKey, passwd, nested} { + if strings.Contains(out, secret) { + t.Errorf("default output leaks %q:\n%s", secret, out) + } + } + if strings.HasPrefix(strings.TrimSpace(out), "{") { + t.Errorf("default output is JSON, want logfmt:\n%s", out) + } +}