fix(diary): retry a daily file that failed to open

- 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)
This commit is contained in:
Jakub Zych
2026-10-22 02:25:18 +02:00
parent 9b62285654
commit c586c6f8a9
4 changed files with 114 additions and 21 deletions

View File

@@ -97,7 +97,7 @@ Every record carries the attribute `component=blog`, and passes the component's
A daily channel with `path: storage/logs/summer.log` writes `storage/logs/summer-2026-10-21.log` today and `storage/logs/summer-2026-10-22.log` after local midnight. A relative path resolves against the application root, the directory that holds `config/`, and may not leave it; an absolute path is used as given. Files are created with mode 0640 in directories created with mode 0750, because logs carry user identifiers, and a file is only created once a record reaches it. With `days: 14` the files of today and the 13 days before are kept and older files of the same name pattern are deleted; other files in the directory are never touched. `days: 0` keeps every file.
If the directory cannot be created or the file cannot be opened (a read-only container filesystem, missing permissions), the channel logs one warning from component `diary` on the console naming the path and the error, and is disabled. The start-up never fails because of a log file.
If the directory cannot be created or the file cannot be opened (a read-only container filesystem, missing permissions), the channel logs a warning from component `diary` on the console naming the path and the error, once per day. It then skips records and tries to open the file again one minute later, or at the first record of the next day, whichever comes first, so a passing failure (a full disk, too many open files, a directory removed for a moment during rotation) does not end file logging until the next restart. The start-up never fails because of a log file.
## Redaction

View File

@@ -30,7 +30,7 @@ Use cases:
- Environment overrides: `SUMMER_LOG__` variables overlay the defaults key by key, and string values parse where YAML gives numbers or lists (`SUMMER_LOG__CHANNELS__DAILY__DAYS=30`, `SUMMER_LOG__CHANNELS__STACK__CHANNELS=console,daily`).
- Validation: an unknown driver, format or level, a stack naming a missing channel or containing itself, and a relative daily path that leaves the application root fail `diary.Setup` with an error naming the key.
- Console lines in bonfire's palette: time, level, the component as a fixed-width prefix, the message and `key=value` attributes. Control characters other than tab are removed from messages and values, so logged data cannot inject terminal escape sequences. While a bonfire live view (spinner, progress bar, process view) runs, styled lines print above it through `bonfire.PrintAbove`.
- Daily files: the path `storage/logs/summer.log` gives files `storage/logs/summer-2026-10-21.log`, created mode 0640 in directories created 0750, opened on the first record, rotated at local midnight, and deleted after the retention in days (only files of that name pattern). A relative path resolves against the application root. A directory that cannot be written logs one warning from component `diary` on the console and disables the channel; it never fails the start-up.
- Daily files: the path `storage/logs/summer.log` gives files `storage/logs/summer-2026-10-21.log`, created mode 0640 in directories created 0750, opened on the first record, rotated at local midnight, and deleted after the retention in days (only files of that name pattern). A relative path resolves against the application root. A file that cannot be opened (a directory that cannot be written, a full disk) logs a warning from component `diary` on the console, once per day; the channel skips records and tries again a minute later or at the first record of the next day, and it never fails the start-up.
- Redaction: every channel leaf is wrapped by `sunscreen.Wrap`.
- Runtime verbosity: `diary.SetVerbosity` lets info (1) or debug (2) through for every component and adds source locations on styled lines (3); quiet raises only the console channels to warn.
- Console global options: `diary.FromGlobals` turns `-v`/`-vv`/`-vvv`, `-q` and `--ansi`/`--no-ansi` into `diary.Options`, and `diary.ApplyGlobals` applies them to the running setup (the generated main registers it with `bonfire.OnGlobals`).

View File

@@ -12,23 +12,34 @@ import (
const dateLayout = "2006-01-02"
// dailyRetry is how long a daily writer skips records after a file failed
// to open before it tries again on the same date.
const dailyRetry = time.Minute
// dailyWriter writes to one file per local date: path storage/logs/summer.log
// gives storage/logs/summer-2026-10-21.log. Files open lazily on the first
// write (no empty files), are created 0o640 in directories created 0o750,
// and on every open the files of the same base older than the retention are
// deleted. If a file cannot be opened the writer reports once through warn
// and is disabled: later writes succeed without writing anything.
// deleted. If a file cannot be opened the writer skips records (writes
// still succeed) and tries again one minute later by its clock, or at the
// first record of a new date, whichever comes first; it reports through
// warn once per date that fails.
type dailyWriter struct {
mu sync.Mutex
dir string
base string
ext string
days int
now func() time.Time
warn func(path string, err error)
file *os.File
date string
disabled bool
mu sync.Mutex
dir string
base string
ext string
days int
now func() time.Time
warn func(path string, err error)
file *os.File
date string
// failedDate is the date whose file failed to open last; no open is
// tried for it before retryAt.
failedDate string
retryAt time.Time
// warnedDate is the last date a failure was reported for.
warnedDate string
}
func newDailyWriter(path string, days int, now func() time.Time, warn func(string, error)) *dailyWriter {
@@ -54,15 +65,19 @@ func (d *dailyWriter) fileName(date string) string {
// Write appends p to the current day's file in one write call.
func (d *dailyWriter) Write(p []byte) (int, error) {
d.mu.Lock()
if d.disabled {
d.mu.Unlock()
return len(p), nil
}
date := d.now().Local().Format(dateLayout)
now := d.now()
date := now.Local().Format(dateLayout)
if d.file == nil || date != d.date {
if date == d.failedDate && now.Before(d.retryAt) {
d.mu.Unlock()
return len(p), nil
}
if err := d.open(date); err != nil {
d.disabled = true
warn := d.warn
d.failedDate, d.retryAt = date, now.Add(dailyRetry)
var warn func(string, error)
if d.warnedDate != date {
d.warnedDate, warn = date, d.warn
}
name := d.fileName(date)
d.mu.Unlock()
if warn != nil {
@@ -70,6 +85,7 @@ func (d *dailyWriter) Write(p []byte) (int, error) {
}
return len(p), nil
}
d.failedDate = ""
}
n, err := d.file.Write(p)
d.mu.Unlock()

View File

@@ -9,6 +9,7 @@ import (
"strings"
"syscall"
"testing"
"time"
"git.golem15.com/golem15/summercms/modules/diary"
)
@@ -268,3 +269,79 @@ func TestPathConfinement(t *testing.T) {
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())
}
})
}