c586c6f8a9
- a failed open no longer disables the writer for good: it skips records and tries again one minute later by its clock, or at the first record of a new date, whichever comes first - the warning (still 'daily log file disabled') appears once per date - README and the logging page describe the retry (WR-04)
348 lines
12 KiB
Go
348 lines
12 KiB
Go
//go:build unix
|
|
|
|
package diary_test
|
|
|
|
import (
|
|
"os"
|
|
"path/filepath"
|
|
"slices"
|
|
"strings"
|
|
"syscall"
|
|
"testing"
|
|
"time"
|
|
|
|
"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))
|
|
}
|
|
}
|
|
|
|
// TestDailyRetriesAfterFailure (WR-04): a daily file that failed to open is
|
|
// retried one minute later by the writer's clock, or on the first record of
|
|
// a new date, whichever comes first; the warning appears once per date.
|
|
func TestDailyRetriesAfterFailure(t *testing.T) {
|
|
start := func(t *testing.T, at time.Time) (root string, clk *clock, buf *lockedBuffer) {
|
|
t.Helper()
|
|
root = t.TempDir()
|
|
blocker := filepath.Join(root, "blocker")
|
|
if err := os.WriteFile(blocker, []byte("x"), 0o600); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
clk = newClock(at)
|
|
buf = &lockedBuffer{}
|
|
setup(t, diary.Options{Root: root, Stderr: buf, Now: clk.Now},
|
|
append(slices.Clone(dailyOnly), "SUMMER_LOG__CHANNELS__DAILY__PATH=blocker/logs/summer.log")...)
|
|
return root, clk, buf
|
|
}
|
|
warnings := func(buf *lockedBuffer) int { return strings.Count(buf.String(), "daily log file disabled") }
|
|
blog := diary.For("blog")
|
|
|
|
t.Run("one minute later", func(t *testing.T) {
|
|
root, clk, buf := start(t, day(21, 10, 0, 0))
|
|
blog.Info("first")
|
|
if n := warnings(buf); n != 1 {
|
|
t.Fatalf("%d warnings after the failed open, want 1:\n%s", n, buf.String())
|
|
}
|
|
if err := os.Remove(filepath.Join(root, "blocker")); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
file := filepath.Join(root, "blocker", "logs", "summer-2026-10-21.log")
|
|
clk.Set(day(21, 10, 0, 30))
|
|
blog.Info("within the minute")
|
|
if _, err := os.Stat(file); !os.IsNotExist(err) {
|
|
t.Fatalf("retried before the minute passed (stat err %v)", err)
|
|
}
|
|
if n := warnings(buf); n != 1 {
|
|
t.Fatalf("%d warnings within the minute, want 1:\n%s", n, buf.String())
|
|
}
|
|
clk.Set(day(21, 10, 1, 1))
|
|
blog.Info("after the minute")
|
|
lines := readDaily(t, file)
|
|
if len(lines) != 1 || !strings.Contains(lines[0], "after the minute") {
|
|
t.Fatalf("daily file after the retry = %q, want the record after the minute", lines)
|
|
}
|
|
})
|
|
|
|
t.Run("next date", func(t *testing.T) {
|
|
root, clk, buf := start(t, day(21, 23, 59, 59))
|
|
blog.Info("before midnight")
|
|
if err := os.Remove(filepath.Join(root, "blocker")); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
clk.Set(day(22, 0, 0, 1))
|
|
blog.Info("after midnight")
|
|
lines := readDaily(t, filepath.Join(root, "blocker", "logs", "summer-2026-10-22.log"))
|
|
if len(lines) != 1 || !strings.Contains(lines[0], "after midnight") {
|
|
t.Fatalf("daily file of the new date = %q", lines)
|
|
}
|
|
if n := warnings(buf); n != 1 {
|
|
t.Errorf("%d warnings, want 1:\n%s", n, buf.String())
|
|
}
|
|
})
|
|
|
|
t.Run("next date fails too", func(t *testing.T) {
|
|
_, clk, buf := start(t, day(21, 23, 59, 59))
|
|
blog.Info("before midnight")
|
|
clk.Set(day(22, 0, 0, 1))
|
|
blog.Info("after midnight")
|
|
clk.Set(day(22, 0, 2, 0))
|
|
blog.Info("later")
|
|
if n := warnings(buf); n != 2 {
|
|
t.Errorf("%d warnings over two failed dates, want 2:\n%s", n, buf.String())
|
|
}
|
|
})
|
|
}
|