From f9b8770303693e72a52d312b0c29489e26ed54784c04239f9838cf3b0915b4e8 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 15 Oct 2026 19:57:31 +0000 Subject: [PATCH] v0.1.13 follow a replaced, removed, moved log file properly --- benchmark_test.go | 41 ++++++++++- constant.go | 3 + doc/heartbeat.md | 3 +- doc/storage.md | 20 +++++- heartbeat.go | 1 + logger.go | 1 + processor.go | 36 +++++++--- state.go | 1 + storage.go | 132 +++++++++++++++++++++++++--------- storage_nofs.go | 8 ++- storage_test.go | 165 +++++++++++++++++++++++++++++++++++++++++++ storage_unix.go | 3 + storage_unix_test.go | 51 +++++++++++++ type.go | 11 +++ 14 files changed, 425 insertions(+), 51 deletions(-) create mode 100644 storage_unix_test.go diff --git a/benchmark_test.go b/benchmark_test.go index 4d20772..c4ebbe6 100644 --- a/benchmark_test.go +++ b/benchmark_test.go @@ -2,11 +2,12 @@ package log import ( "testing" + "time" ) -// These benchmarks measure the producer path: format selection, channel send, -// and drop accounting. File writes complete asynchronously in the processor and -// are not attributed to the measured iterations. +// The benchmarks up to BenchmarkProcessLogRecord measure the producer path: +// format selection, channel send, and drop accounting. File writes complete +// asynchronously in the processor and are not attributed to their iterations. // BenchmarkLoggerInfo measures the default raw-format path. func BenchmarkLoggerInfo(b *testing.B) { @@ -95,3 +96,37 @@ func BenchmarkConcurrentLogging(b *testing.B) { } }) } + +// BenchmarkProcessLogRecord measures the processor's write path, which the +// producer benchmarks above do not see. Record stamps advance by step to stand +// for a logging rate: at 100/s every record is due a log path check. +func BenchmarkProcessLogRecord(b *testing.B) { + for _, bc := range []struct { + name string + step time.Duration // 0: time.Now per record, as emit stamps it + }{{"ts=now", 0}, {"rate=1k/s", time.Millisecond}, {"rate=100/s", 10 * time.Millisecond}} { + b.Run(bc.name, func(b *testing.B) { + l := NewLogger() + c := DefaultConfig() + c.EnableConsole = false + c.EnableFile = true + c.Directory = b.TempDir() + c.Format = "txt" + c.MaxSizeKB = 0 + mustNoErr(b, l.ApplyConfig(c), "ApplyConfig") // not started: the benchmark is the processor + b.Cleanup(func() { _ = l.Shutdown() }) + rec := logRecord{Flags: l.getFlags(), Level: LevelInfo, Args: []any{"benchmark message", 42}} + ts := time.Now() + b.ReportAllocs() + for b.Loop() { + if ts = ts.Add(bc.step); bc.step == 0 { + ts = time.Now() + } + rec.TimeStamp = ts + if l.processLogRecord(rec) == 0 { + b.Fatal("record not written") + } + } + }) + } +} diff --git a/constant.go b/constant.go index 1be13ff..19aee3b 100644 --- a/constant.go +++ b/constant.go @@ -55,6 +55,9 @@ const ( const ( // Minimum wait time used throughout the package minWaitTime = 10 * time.Millisecond + // Record time between checks that the log path still names the open file; + // bounds the writes lost to a file replaced or removed under the logger + fileCheckInterval = 10 * time.Millisecond // Factors to adjust check interval adaptiveIntervalFactor float64 = 1.5 // Slow down adaptiveSpeedUpFactor float64 = 0.8 // Speed up diff --git a/doc/heartbeat.md b/doc/heartbeat.md index 0fa71d7..6e90246 100644 --- a/doc/heartbeat.md +++ b/doc/heartbeat.md @@ -61,12 +61,13 @@ logger.ApplyConfigString( **Additional Output:** ``` -2024-01-15T10:30:00Z DISK type=disk sequence=1 rotated_files=12 deleted_files=5 total_log_size_mb="487.32" log_file_count=8 current_file_size_mb="23.45" disk_status_ok=true disk_free_mb="5234.67" +2024-01-15T10:30:00Z DISK type=disk sequence=1 rotated_files=12 deleted_files=5 reopened_files=1 total_log_size_mb="487.32" log_file_count=8 current_file_size_mb="23.45" disk_status_ok=true disk_free_mb="5234.67" ``` **Additional Fields:** - `rotated_files`: Total file rotations - `deleted_files`: Files removed by cleanup +- `reopened_files`: Log paths opened again after an external rename or removal - `total_log_size_mb`: Size of all log files - `log_file_count`: Number of log files - `current_file_size_mb`: Active file size diff --git a/doc/storage.md b/doc/storage.md index b795395..e417ee3 100644 --- a/doc/storage.md +++ b/doc/storage.md @@ -17,12 +17,26 @@ logger.ApplyConfigString( ### Rotation Behavior 1. Before each write, the logger checks whether the active file would exceed `max_size_kb`. -2. It closes the active `{name}.{extension}` file and renames it to `{name}_{YYMMDD}_{HHMMSS}[_N].{extension}`. +2. It closes the active `{name}.{extension}` file and renames it to `{name}_{YYMMDD}_{HHMMSS}[_N].{extension}`; a file already removed leaves nothing to archive. 3. It opens a new active file. A counter suffix avoids existing names when rotations share a second. For example: `myapp.log` becomes `myapp_240115_143022.log`, then `myapp_240115_143022_1.log` on the next collision. Rotation does not split a record, so a single oversized record can exceed the size limit. File errors can drop records and are counted. Periodic sync, explicit `Flush`, and shutdown provide sync points; closing a file alone does not guarantee crash durability. -Use a directory owned exclusively by this logger. Cleanup and retention select regular files by extension, including files from earlier runs with different base names. They exclude the active filename, directories, and symlinks. With an empty extension, only extensionless files match. Console-only configurations never perform retention deletion. Total-size and free-space limits are checked periodically and can be exceeded between checks. +Use a directory owned exclusively by this logger. Cleanup and retention select regular files by extension, including files from earlier runs with different base names. They exclude the active filename, the file being written under any name, directories, and symlinks. With an empty extension, only extensionless files match. Console-only configurations never perform retention deletion. Total-size and free-space limits are checked periodically and can be exceeded between checks. + +### External Edits and Rotation + +The logger writes with `O_APPEND` to whatever file its path names. It checks the path at most once per 10 ms of record time, and at every `Flush`, at `Stop` and before a size rotation. + +- Edited in place: `truncate -s 0`, `: > app.log`, nano, `echo note >> app.log`, logrotate `copytruncate`. + - The next record lands at the new end of the file; the tracked size is re-read at each check. +- Replaced, removed or moved: vim (it saves by renaming), `sed -i`, `perl -i`, `rm`, `mv`, logrotate `create`. + - The path is opened again, and created if missing; no signal or reopen call is needed. + - Records written between the change and that check go to the old file: lost with a removed file, kept in a moved one. + - On unix the reopen never follows a symlink and keeps only a regular file. A refusal is reported once as an internal error (`SetErrorHandler`, or stderr with `internal_errors_to_stderr`), and the old handle stays in use until the path is usable. The first open in `ApplyConfig` still follows a symlinked path. + - On Windows the open file cannot be renamed or removed while the logger holds it. + - Disk heartbeats count reopens as `reopened_files`. +- Not preventable by a writer: an editor saves the snapshot it read, overwriting records logged while it had the file open (vim and nano warn first). A note without a final newline joins the next record's line. ## Disk Space Management @@ -149,7 +163,7 @@ logger.ApplyConfigString( Output: ``` -2024-01-15T10:30:00Z DISK type="disk" sequence=1 rotated_files=5 deleted_files=2 total_log_size_mb="487.32" log_file_count=8 current_file_size_mb="23.45" disk_status_ok=true disk_free_mb="5234.67" +2024-01-15T10:30:00Z DISK type="disk" sequence=1 rotated_files=5 deleted_files=2 reopened_files=0 total_log_size_mb="487.32" log_file_count=8 current_file_size_mb="23.45" disk_status_ok=true disk_free_mb="5234.67" ``` ## Manual Recovery diff --git a/heartbeat.go b/heartbeat.go index 2e57cd9..123dbed 100644 --- a/heartbeat.go +++ b/heartbeat.go @@ -92,6 +92,7 @@ func (l *Logger) logDiskHeartbeat() { "sequence", sequence, "rotated_files", rotations, "deleted_files", deletions, + "reopened_files", l.state.TotalReopens.Load(), "total_log_size_mb", fmt.Sprintf("%.2f", totalSizeMB), "log_file_count", fileCount, "current_file_size_mb", fmt.Sprintf("%.2f", currentSizeMB), diff --git a/logger.go b/logger.go index 663d1e4..bf87cdc 100644 --- a/logger.go +++ b/logger.go @@ -27,6 +27,7 @@ type Logger struct { initMu sync.Mutex // serializes lifecycle and configuration changes sendMu sync.RWMutex // joins enqueues before detaching a processor processorErr error // written by processor, read only after ProcDone closes + watch fileWatch // processor goroutine only } // levelOff closes the emit gate without touching configuration diff --git a/processor.go b/processor.go index 5038057..b394429 100644 --- a/processor.go +++ b/processor.go @@ -51,6 +51,7 @@ func (l *Logger) processLogs(ch <-chan logRecord, stop <-chan struct{}, done cha for { select { case <-stop: + l.checkLogPath(time.Now(), true) l.drain(ch) l.processorErr = l.performSync() return @@ -107,7 +108,10 @@ func (l *Logger) drain(ch <-chan logRecord) { } } +// handleFlushRequest also reattaches a replaced log path before draining, so a +// Flush is a deterministic point to follow an external rotation func (l *Logger) handleFlushRequest(ch <-chan logRecord, request flushRequest) { + l.checkLogPath(time.Now(), true) l.drain(ch) request.done <- l.performSync() } @@ -116,6 +120,14 @@ func (l *Logger) handleFlushRequest(ch <-chan logRecord, request flushRequest) { func (l *Logger) processLogRecord(record logRecord) int64 { c := l.getConfig() enableFile := c.EnableFile + + // Follow the log path when the file was replaced, removed or resized. Before + // the disk gate: removing the file is how an operator frees the space. + now := record.TimeStamp + if now.IsZero() { + now = time.Now() + } + checked := enableFile && l.checkLogPath(now, false) if enableFile && !l.state.DiskStatusOK.Load() { // Simple increment of both counters l.handleFailedSend() @@ -171,17 +183,19 @@ func (l *Logger) processLogRecord(record logRecord) int64 { return formattedDataLen // Return data length for adaptive interval calculations } - // File rotation check - currentFileSize := l.state.CurrentSize.Load() - estimatedSize := currentFileSize + formattedDataLen - - maxSizeKB := c.MaxSizeKB - if maxSizeKB > 0 && estimatedSize > maxSizeKB*sizeMultiplier { - if err := l.rotateLogFile(); err != nil { - l.internalLog("failed to rotate log file: %v\n", err) - // Account for the dropped log that triggered the failed rotation - l.handleFailedSend() - return 0 + // File rotation check, on the size read from the file: an external edit + // since the last check leaves CurrentSize stale + if maxSize := c.MaxSizeKB * sizeMultiplier; maxSize > 0 && l.state.CurrentSize.Load()+formattedDataLen > maxSize { + if !checked { + l.checkLogPath(now, true) + } + if l.state.CurrentSize.Load()+formattedDataLen > maxSize { + if err := l.rotateLogFile(); err != nil { + l.internalLog("failed to rotate log file: %v\n", err) + // Account for the dropped log that triggered the failed rotation + l.handleFailedSend() + return 0 + } } } diff --git a/state.go b/state.go index 188f358..9d56347 100644 --- a/state.go +++ b/state.go @@ -45,4 +45,5 @@ type State struct { TotalLogsProcessed atomic.Uint64 // Counter for non-heartbeat logs successfully processed TotalRotations atomic.Uint64 // Counter for successful log rotations TotalDeletions atomic.Uint64 // Counter for successful log deletions (cleanup/retention) + TotalReopens atomic.Uint64 // Counter for log paths reopened after an external rename or removal } diff --git a/storage.go b/storage.go index f670fea..89d70b9 100644 --- a/storage.go +++ b/storage.go @@ -1,7 +1,9 @@ package log import ( + "errors" "fmt" + "io/fs" "os" "path/filepath" "sort" @@ -175,13 +177,14 @@ func (l *Logger) cleanOldLogs(required int64) error { modTime time.Time size int64 } + active := l.openFileInfo() var logs []logFileMeta for _, entry := range entries { if !matchesLogEntry(entry, ext) || entry.Name() == staticLogName { continue } info, errInfo := entry.Info() - if errInfo != nil { + if errInfo != nil || os.SameFile(info, active) { continue } logs = append(logs, logFileMeta{name: entry.Name(), modTime: info.ModTime(), size: info.Size()}) @@ -292,12 +295,13 @@ func (l *Logger) cleanExpiredLogs(oldest time.Time) error { staticLogName = name + "." + ext } + active := l.openFileInfo() for _, entry := range entries { if !matchesLogEntry(entry, ext) || entry.Name() == staticLogName { continue } info, errInfo := entry.Info() - if errInfo != nil { + if errInfo != nil || os.SameFile(info, active) { continue } if info.ModTime().Before(cutoffTime) { @@ -313,6 +317,17 @@ func (l *Logger) cleanExpiredLogs(oldest time.Time) error { return nil } +// openFileInfo identifies the file being written; cleanup spares it under any +// name, as it may have been renamed since the last path check +func (l *Logger) openFileInfo() os.FileInfo { + if file, _ := l.state.CurrentFile.Load().(*os.File); file != nil { + if info, err := file.Stat(); err == nil { + return info + } + } + return nil +} + // getStaticLogFilePath returns the full path to the active log file func (l *Logger) getStaticLogFilePath() string { c := l.getConfig() @@ -353,11 +368,6 @@ func (l *Logger) generateArchiveLogFileName(timestamp time.Time) string { return name } -// createNewLogFile opens the active log file in append mode -func (l *Logger) createNewLogFile() (*os.File, error) { - return openLogFile(l.getConfig()) -} - func openLogFile(c *Config) (*os.File, error) { name := c.Name if c.Extension != "" { @@ -371,35 +381,93 @@ func openLogFile(c *Config) (*os.File, error) { return file, nil } +// openLogPath opens the log path again after a rotation or an external change. +// Unlike the configured first open it never follows a symlink, never blocks on +// a FIFO, and keeps only a regular file: the path may have been replaced. +func openLogPath(path string) (*os.File, os.FileInfo, error) { + file, err := os.OpenFile(path, reopenFlags, 0644) + if err != nil { + return nil, nil, fmtErrorf("failed to open/create log file '%s': %w", path, err) + } + info, err := file.Stat() + if err == nil && !info.Mode().IsRegular() { + err = errors.New("not a regular file") + } + if err != nil { + _ = file.Close() + return nil, nil, fmtErrorf("refused log file '%s': %w", path, err) + } + return file, info, nil +} + +// checkLogPath keeps the processor on its log path. At most once per +// fileCheckInterval of record time, or when forced, it compares the path with +// the open file: a path that is gone or names another file (rename-on-save +// editors, sed -i, rm, mv) is opened afresh. CurrentSize is resynced from the +// file either way. Reports whether the check ran. Processor goroutine only. +func (l *Logger) checkLogPath(now time.Time, force bool) bool { + w := &l.watch + if !force && now.Sub(w.lastCheck) < fileCheckInterval { + return false + } + w.lastCheck = now + + file, _ := l.state.CurrentFile.Load().(*os.File) + if file == nil { + return true + } + if w.file != file { + info, err := file.Stat() + if err != nil { + w.file = nil + return true // unusable handle: the write reports it + } + w.file, w.info, w.path = file, info, l.getStaticLogFilePath() + } + + pathInfo, err := os.Stat(w.path) + if err == nil && os.SameFile(pathInfo, w.info) { + l.state.CurrentSize.Store(pathInfo.Size()) + w.warned = false + return true + } + if errors.Is(err, fs.ErrPermission) { + return true // cannot tell: keep the open file + } + newFile, info, err := openLogPath(w.path) + if err != nil { + if !w.warned { + w.warned = true + l.internalLog("log path no longer names the open file, not reopened: %v\n", err) + } + return true + } + l.state.CurrentFile.Store(newFile) + if err := file.Close(); err != nil { + l.internalLog("failed to close replaced log file: %v\n", err) + } + w.file, w.info, w.warned = newFile, info, false + l.state.CurrentSize.Store(info.Size()) + l.state.TotalReopens.Add(1) + return true +} + // rotateLogFile implements the rename-on-rotate strategy // Closes current file, renames it with timestamp, creates new static file func (l *Logger) rotateLogFile() error { c := l.getConfig() + currentPath := l.getStaticLogFilePath() - // Get current file handle - cfPtr := l.state.CurrentFile.Load() - if cfPtr == nil { + currentFile, _ := l.state.CurrentFile.Load().(*os.File) + if currentFile == nil { // This can happen if file logging was disabled and re-enabled // No current file, just create a new one - newFile, err := l.createNewLogFile() + newFile, info, err := openLogPath(currentPath) if err != nil { return fmtErrorf("failed to create log file during rotation: %w", err) } l.state.CurrentFile.Store(newFile) - l.state.CurrentSize.Store(0) - l.state.TotalRotations.Add(1) - return nil - } - - currentFile, ok := cfPtr.(*os.File) - if !ok || currentFile == nil { - // Invalid file handle in state, treat as if there's no file - newFile, err := l.createNewLogFile() - if err != nil { - return fmtErrorf("failed to create log file during rotation: %w", err) - } - l.state.CurrentFile.Store(newFile) - l.state.CurrentSize.Store(0) + l.state.CurrentSize.Store(info.Size()) l.state.TotalRotations.Add(1) return nil } @@ -413,13 +481,13 @@ func (l *Logger) rotateLogFile() error { l.state.CurrentFile.Store((*os.File)(nil)) // Generate a new unique name with current timestamp for the old log file - dir := c.Directory - archiveName := l.generateArchiveLogFileName(time.Now()) - archivePath := filepath.Join(dir, archiveName) + archivePath := filepath.Join(c.Directory, l.generateArchiveLogFileName(time.Now())) // Rename current file to archive name - currentPath := l.getStaticLogFilePath() - if err := os.Rename(currentPath, archivePath); err != nil { + if err := os.Rename(currentPath, archivePath); errors.Is(err, fs.ErrNotExist) { + // Removed since the last path check: nothing to archive + l.internalLog("log file '%s' was removed before rotation, nothing to archive\n", currentPath) + } else if err != nil { // Critical failure: the original file is closed and couldn't be renamed // This is a terminal state for file logging l.internalLog("failed to rename log file from '%s' to '%s': %v. file logging disabled.", @@ -430,7 +498,7 @@ func (l *Logger) rotateLogFile() error { } // Create new log file at static path - newFile, err := l.createNewLogFile() + newFile, info, err := openLogPath(currentPath) if err != nil { l.state.LoggerDisabled.Store(true) l.refreshLevelGate() @@ -439,7 +507,7 @@ func (l *Logger) rotateLogFile() error { // Update state l.state.CurrentFile.Store(newFile) - l.state.CurrentSize.Store(0) + l.state.CurrentSize.Store(info.Size()) l.state.TotalRotations.Add(1) // Update earliest file time after successful rotation diff --git a/storage_nofs.go b/storage_nofs.go index 8b760a8..f64ea31 100644 --- a/storage_nofs.go +++ b/storage_nofs.go @@ -2,7 +2,13 @@ package log -import "math" +import ( + "math" + "os" +) + +// reopenFlags open the log path again; see openLogPath +const reopenFlags = os.O_APPEND | os.O_CREATE | os.O_WRONLY // getDiskFreeSpace reports unlimited space where statfs is unavailable. // Total-size limits still apply; only the free-space check is inert. diff --git a/storage_test.go b/storage_test.go index 77db85f..64d0c7e 100644 --- a/storage_test.go +++ b/storage_test.go @@ -4,7 +4,9 @@ import ( "fmt" "os" "path/filepath" + "slices" "strings" + "sync" "testing" "time" ) @@ -218,3 +220,166 @@ func TestArchiveNaming(t *testing.T) { isTrue(t, strings.HasPrefix(second, "log_"), "archive prefix") isTrue(t, strings.HasSuffix(second, ".log"), "archive extension") } + +// followLogger returns a started txt logger writing dir/app.log, and the +// diagnostics it reported +func followLogger(t *testing.T, maxKB int64) (*Logger, string, func() []string) { + t.Helper() + l := NewLogger() + var mu sync.Mutex + var diags []string + l.SetErrorHandler(func(s string) { mu.Lock(); diags = append(diags, s); mu.Unlock() }) + c := DefaultConfig() + c.EnableConsole = false + c.EnableFile = true + c.Directory = t.TempDir() + c.Name = "app" + c.Format = "txt" + c.MaxSizeKB = maxKB + c.MaxTotalSizeKB = 0 + c.MinDiskFreeKB = 0 + mustNoErr(t, l.ApplyConfig(c), "ApplyConfig") + mustNoErr(t, l.Start(), "Start") + t.Cleanup(func() { _ = l.Shutdown() }) + return l, filepath.Join(c.Directory, "app.log"), func() []string { + mu.Lock() + defer mu.Unlock() + return slices.Clone(diags) + } +} + +func logFlush(t *testing.T, l *Logger, msgs ...string) { + t.Helper() + for _, m := range msgs { + l.Info(m) + } + mustNoErr(t, l.Flush(time.Second), "Flush") +} + +// logProcessed logs without Flush, whose forced path check would mask the one under test +func logProcessed(t *testing.T, l *Logger, msgs ...string) { + t.Helper() + want := l.state.TotalLogsProcessed.Load() + uint64(len(msgs)) + for _, m := range msgs { + l.Info(m) + } + mustEventually(t, time.Second, "records processed", func() bool { return l.state.TotalLogsProcessed.Load() >= want }) +} + +// replaceFile saves content the way vim, sed -i and perl -i do: a new file renamed over path +func replaceFile(t *testing.T, path, content string) { + t.Helper() + mustNoErr(t, os.WriteFile(path+".tmp", []byte(content), 0644), "write replacement") + mustNoErr(t, os.Rename(path+".tmp", path), "replace") +} + +func TestFollowsReplacedLogFile(t *testing.T) { + l, path, _ := followLogger(t, 0) + logFlush(t, l, "before") + data, err := os.ReadFile(path) + mustNoErr(t, err, "read") + replaceFile(t, path, string(data)+"NOTE by user\n") + time.Sleep(fileCheckInterval + 5*time.Millisecond) // the next record is due a check + logProcessed(t, l, "after") + data, err = os.ReadFile(path) + mustNoErr(t, err, "read") + lines := strings.Split(strings.TrimSuffix(string(data), "\n"), "\n") + mustEqual(t, len(lines), 3, "lines: "+string(data)) + contains(t, lines[0], "before", "kept by the editor") + equal(t, lines[1], "NOTE by user", "note") + contains(t, lines[2], "after", "appended after the note") + equal(t, l.state.TotalReopens.Load(), uint64(1), "reopens") +} + +// The rotation decision follows a replaced file instead of archiving it +func TestRotationFollowsReplacedLogFile(t *testing.T) { + l, path, _ := followLogger(t, 1) // 1000 bytes + for l.state.CurrentSize.Load() < 900 { + logFlush(t, l, "fill-"+strings.Repeat("y", 10)) + } + replaceFile(t, path, "") // all content deleted + pad := strings.Repeat("z", 120) // the first record after the edit crosses the stale size limit + logProcessed(t, l, "a1"+pad, "a2"+pad, "a3"+pad) + data, err := os.ReadFile(path) + mustNoErr(t, err, "read") + equal(t, strings.Count(string(data), pad), 3, "records after the edit: "+string(data)) + equal(t, l.state.TotalRotations.Load(), uint64(0), "rotations") +} + +// Truncation leaves the tracked size stale; rotation must use the real size +func TestRotationAfterTruncateUsesFileSize(t *testing.T) { + l, path, _ := followLogger(t, 2) // 2000 bytes + for l.state.CurrentSize.Load() < 1800 { + logFlush(t, l, "fill-"+strings.Repeat("y", 10)) + } + mustNoErr(t, os.Truncate(path, 0), "truncate") + logProcessed(t, l, "a1", "a2", "a3", "a4", "a5", "a6", "a7", "a8", "a9", "a10") + equal(t, l.state.TotalRotations.Load(), uint64(0), "rotations") + fi, err := os.Stat(path) + mustNoErr(t, err, "stat") + equal(t, l.state.CurrentSize.Load(), fi.Size(), "tracked size") +} + +// A file removed under the logger leaves nothing to archive, not a disabled logger +func TestRotateRemovedLogFile(t *testing.T) { + l, path, _ := followLogger(t, 0) + mustNoErr(t, l.Stop(5*time.Second), "Stop") // own the file state from the test goroutine + mustNoErr(t, os.Remove(path), "rm") + mustNoErr(t, l.rotateLogFile(), "rotate") + isFalse(t, l.state.LoggerDisabled.Load(), "logger disabled") + _, err := os.Stat(path) + mustNoErr(t, err, "new active file") +} + +// Flush and Stop reattach a moved log path at once, as after logrotate's create +// mode; no record is processed in between, so only their check can reopen +func TestFlushAndStopReattachMovedLogFile(t *testing.T) { + for name, barrier := range map[string]func(l *Logger) error{ + "flush": func(l *Logger) error { return l.Flush(time.Second) }, + "stop": func(l *Logger) error { return l.Stop(5 * time.Second) }, + } { + t.Run(name, func(t *testing.T) { + l, path, _ := followLogger(t, 0) + logFlush(t, l, "before") + mustNoErr(t, os.Rename(path, path+".1"), "mv") + mustNoErr(t, barrier(l), name) + _, err := os.Stat(path) + mustNoErr(t, err, "path recreated") + equal(t, l.state.TotalReopens.Load(), uint64(1), "reopens") + }) + } +} + +// Cleanup never deletes the file being written, whatever it is now named +func TestCleanupSparesOpenFile(t *testing.T) { + l, path, _ := followLogger(t, 0) + logFlush(t, l, "before") + mustNoErr(t, l.Stop(5*time.Second), "Stop") // own the file state from the test goroutine + moved := filepath.Join(filepath.Dir(path), "app-keep.log") + mustNoErr(t, os.Rename(path, moved), "mv") + old := time.Now().Add(-48 * time.Hour) + mustNoErr(t, os.Chtimes(moved, old, old), "age") + c := l.GetConfig() + c.RetentionPeriodHrs = 1 + mustNoErr(t, l.ApplyConfig(c), "ApplyConfig") + + errContains(t, l.cleanOldLogs(1), "no old logs", "size cleanup") + mustNoErr(t, l.cleanExpiredLogs(old), "retention cleanup") + _, err := os.Stat(moved) + mustNoErr(t, err, "open file kept") + equal(t, l.state.TotalDeletions.Load(), uint64(0), "deletions") +} + +// A file removed to free disk space is followed while records are dropped for +// that low space, so the unlinked inode is released +func TestFollowsRemovedLogFileWhileDiskLow(t *testing.T) { + l, path, _ := followLogger(t, 0) + logFlush(t, l, "before") + l.state.DiskStatusOK.Store(false) // as when min_disk_free_kb is not met + mustNoErr(t, os.Remove(path), "rm") + time.Sleep(fileCheckInterval + 5*time.Millisecond) + l.Info("dropped") + mustEventually(t, time.Second, "path recreated", func() bool { return l.state.TotalReopens.Load() == 1 }) + _, err := os.Stat(path) + mustNoErr(t, err, "path") +} diff --git a/storage_unix.go b/storage_unix.go index 3de700f..a7c35a1 100644 --- a/storage_unix.go +++ b/storage_unix.go @@ -8,6 +8,9 @@ import ( "syscall" ) +// reopenFlags open the log path again; see openLogPath +const reopenFlags = os.O_APPEND | os.O_CREATE | os.O_WRONLY | syscall.O_NOFOLLOW | syscall.O_NONBLOCK + // getDiskFreeSpace retrieves available disk space for the given path func (l *Logger) getDiskFreeSpace(path string) (int64, error) { var stat syscall.Statfs_t diff --git a/storage_unix_test.go b/storage_unix_test.go new file mode 100644 index 0000000..65d1ddb --- /dev/null +++ b/storage_unix_test.go @@ -0,0 +1,51 @@ +//go:build linux || freebsd || darwin + +package log + +import ( + "os" + "path/filepath" + "strings" + "syscall" + "testing" + "time" +) + +// A symlink or FIFO planted at the log path is neither followed nor allowed to +// block the processor; a FIFO that opens is still not a regular file. The +// refusal is reported once. +func TestReopenRefusesNonRegularPath(t *testing.T) { + plant := map[string]func(t *testing.T, path, target string){ + "symlink": func(t *testing.T, path, target string) { + mustNoErr(t, os.WriteFile(target, nil, 0644), "target") + mustNoErr(t, os.Symlink(target, path), "symlink") + }, + "fifo": func(t *testing.T, path, _ string) { + mustNoErr(t, syscall.Mkfifo(path, 0644), "mkfifo") + }, + "fifo with a reader": func(t *testing.T, path, _ string) { + mustNoErr(t, syscall.Mkfifo(path, 0644), "mkfifo") + r, err := os.OpenFile(path, os.O_RDONLY|syscall.O_NONBLOCK, 0) + mustNoErr(t, err, "reader") + t.Cleanup(func() { _ = r.Close() }) + }, + } + for name, fn := range plant { + t.Run(name, func(t *testing.T) { + l, path, diags := followLogger(t, 0) + logFlush(t, l, "before") + target := filepath.Join(t.TempDir(), "target") + mustNoErr(t, os.Remove(path), "rm") + fn(t, path, target) + time.Sleep(fileCheckInterval + 5*time.Millisecond) + logFlush(t, l, "after") // a blocked processor fails the Flush + if data, err := os.ReadFile(target); err == nil { + equal(t, len(data), 0, "bytes written through the symlink") + } + equal(t, l.state.TotalReopens.Load(), uint64(0), "reopens") + if d := diags(); len(d) != 1 || !strings.Contains(d[0], "not reopened") { + t.Errorf("diagnostics %q", d) + } + }) + } +} diff --git a/type.go b/type.go index 8b8ede5..f870e6d 100644 --- a/type.go +++ b/type.go @@ -2,6 +2,7 @@ package log import ( "io" + "os" "time" "github.com/lixenwraith/log/formatter" @@ -35,6 +36,16 @@ type TimerSet struct { diskInterval time.Duration } +// fileWatch records which file the processor's handle refers to. Holding file +// keeps its address from being reused by a later handle. Processor only. +type fileWatch struct { + file *os.File // handle info was taken from + info os.FileInfo // identity of file + path string // log path for file; it changes only with a new file + lastCheck time.Time // record time of the last path check + warned bool // a refused or failed reopen was reported +} + // sink holds the console writers in one atomic.Value; warn takes split's // warn-and-above records type sink struct {