From 035b6a1cdb0f561c84feb13faf73131ee2a6bbe5 Mon Sep 17 00:00:00 2001 From: Daniel Nephin Date: Mon, 23 Nov 2020 14:57:06 -0500 Subject: [PATCH] Merge pull request #9012 from hashicorp/dnephin/log-fix-rotation logging: prune logs on startup --- logging/logfile.go | 32 +++++---- logging/logfile_test.go | 139 ++++++++++++++++++---------------------- logging/logger.go | 31 +++------ 3 files changed, 91 insertions(+), 111 deletions(-) diff --git a/logging/logfile.go b/logging/logfile.go index ff0f324306..153473482f 100644 --- a/logging/logfile.go +++ b/logging/logfile.go @@ -4,6 +4,7 @@ import ( "fmt" "os" "path/filepath" + "sort" "strconv" "strings" "sync" @@ -93,23 +94,28 @@ func (l *LogFile) pruneFiles() error { if l.MaxFiles == 0 { return nil } - pattern := l.fileNamePattern() - //get all the files that match the log file pattern - globExpression := filepath.Join(l.logPath, fmt.Sprintf(pattern, "*")) - matches, err := filepath.Glob(globExpression) + + pattern := filepath.Join(l.logPath, fmt.Sprintf(l.fileNamePattern(), "*")) + matches, err := filepath.Glob(pattern) if err != nil { return err } - var stale int - if l.MaxFiles <= -1 { - // Prune everything - stale = len(matches) - } else { - // Prune if there are more files stored than the configured max - stale = len(matches) - l.MaxFiles + + switch { + case l.MaxFiles < 0: + return removeFiles(matches) + case len(matches) < l.MaxFiles: + return nil } - for i := 0; i < stale; i++ { - if err := os.Remove(matches[i]); err != nil { + + sort.Strings(matches) + last := len(matches) - l.MaxFiles + return removeFiles(matches[:last]) +} + +func removeFiles(files []string) error { + for _, file := range files { + if err := os.Remove(file); err != nil { return err } } diff --git a/logging/logfile_test.go b/logging/logfile_test.go index 115f1bcff4..d56e4d42c0 100644 --- a/logging/logfile_test.go +++ b/logging/logfile_test.go @@ -2,135 +2,122 @@ package logging import ( "io/ioutil" + "os" "path/filepath" + "sort" "testing" "time" + "github.com/stretchr/testify/require" + "github.com/hashicorp/consul/sdk/testutil" ) -const ( - testFileName = "Consul.log" - testDuration = 50 * time.Millisecond - testBytes = 10 -) - -func TestLogFile_timeRotation(t *testing.T) { - tempDir := testutil.TempDir(t, "LogWriterTime") +func TestLogFile_Rotation_MaxDuration(t *testing.T) { + tempDir := testutil.TempDir(t, "") logFile := LogFile{ - fileName: testFileName, + fileName: "consul.log", logPath: tempDir, - duration: testDuration, + duration: 50 * time.Millisecond, } + logFile.Write([]byte("Hello World")) - time.Sleep(3 * testDuration) + time.Sleep(3 * logFile.duration) logFile.Write([]byte("Second File")) - want := 2 - if got, _ := ioutil.ReadDir(tempDir); len(got) != want { - t.Errorf("Expected %d files, got %v file(s)", want, len(got)) - } + require.Len(t, listDir(t, tempDir), 2) } func TestLogFile_openNew(t *testing.T) { - tempDir := testutil.TempDir(t, "LogWriterOpen") - logFile := LogFile{fileName: testFileName, logPath: tempDir, duration: testDuration} - if err := logFile.openNew(); err != nil { - t.Errorf("Expected open file %s, got an error (%s)", testFileName, err) + logFile := LogFile{ + fileName: "consul.log", + logPath: testutil.TempDir(t, ""), + duration: defaultRotateDuration, } + err := logFile.openNew() + require.NoError(t, err) - if _, err := ioutil.ReadFile(logFile.FileInfo.Name()); err != nil { - t.Errorf("Expected readable file %s, got an error (%s)", logFile.FileInfo.Name(), err) - } + msg := "[INFO] Something" + _, err = logFile.Write([]byte(msg)) + require.NoError(t, err) + + content, err := ioutil.ReadFile(logFile.FileInfo.Name()) + require.NoError(t, err) + require.Contains(t, string(content), msg) } -func TestLogFile_byteRotation(t *testing.T) { +func TestLogFile_Rotation_MaxBytes(t *testing.T) { tempDir := testutil.TempDir(t, "LogWriterBytes") logFile := LogFile{ - fileName: testFileName, + fileName: "somefile.log", logPath: tempDir, - MaxBytes: testBytes, - duration: 24 * time.Hour, + MaxBytes: 10, + duration: defaultRotateDuration, } logFile.Write([]byte("Hello World")) logFile.Write([]byte("Second File")) - want := 2 - tempFiles, _ := ioutil.ReadDir(tempDir) - if got := tempFiles; len(got) != want { - t.Errorf("Expected %d files, got %v file(s)", want, len(got)) - } + require.Len(t, listDir(t, tempDir), 2) } -func TestLogFile_deleteArchives(t *testing.T) { - tempDir := testutil.TempDir(t, "LogWriteDeleteArchives") +func TestLogFile_PruneFiles(t *testing.T) { + tempDir := testutil.TempDir(t, t.Name()) logFile := LogFile{ - fileName: testFileName, + fileName: "consul.log", logPath: tempDir, - MaxBytes: testBytes, - duration: 24 * time.Hour, + MaxBytes: 10, + duration: defaultRotateDuration, MaxFiles: 1, } logFile.Write([]byte("[INFO] Hello World")) logFile.Write([]byte("[INFO] Second File")) logFile.Write([]byte("[INFO] Third File")) - want := 2 - tempFiles, _ := ioutil.ReadDir(tempDir) - if got := tempFiles; len(got) != want { - t.Errorf("Expected %d files, got %v file(s)", want, len(got)) - return - } - for _, tempFile := range tempFiles { - var bytes []byte - var err error - path := filepath.Join(tempDir, tempFile.Name()) - if bytes, err = ioutil.ReadFile(path); err != nil { - t.Errorf(err.Error()) - return - } - contents := string(bytes) - if contents == "[INFO] Hello World" { - t.Errorf("Should have deleted the eldest log file") - return - } - } + logFiles := listDir(t, tempDir) + sort.Strings(logFiles) + require.Len(t, logFiles, 2) + + content, err := ioutil.ReadFile(filepath.Join(tempDir, logFiles[0])) + require.NoError(t, err) + require.Contains(t, string(content), "Second File") + + content, err = ioutil.ReadFile(filepath.Join(tempDir, logFiles[1])) + require.NoError(t, err) + require.Contains(t, string(content), "Third File") } -func TestLogFile_deleteArchivesDisabled(t *testing.T) { +func TestLogFile_PruneFiles_Disabled(t *testing.T) { tempDir := testutil.TempDir(t, t.Name()) logFile := LogFile{ - fileName: testFileName, + fileName: "somename.log", logPath: tempDir, - MaxBytes: testBytes, - duration: 24 * time.Hour, + MaxBytes: 10, + duration: defaultRotateDuration, MaxFiles: 0, } logFile.Write([]byte("[INFO] Hello World")) logFile.Write([]byte("[INFO] Second File")) logFile.Write([]byte("[INFO] Third File")) - want := 3 - tempFiles, _ := ioutil.ReadDir(tempDir) - if got := tempFiles; len(got) != want { - t.Errorf("Expected %d files, got %v file(s)", want, len(got)) - return - } + require.Len(t, listDir(t, tempDir), 3) } -func TestLogFile_rotationDisabled(t *testing.T) { +func TestLogFile_FileRotation_Disabled(t *testing.T) { tempDir := testutil.TempDir(t, t.Name()) logFile := LogFile{ - fileName: testFileName, + fileName: "consul.log", logPath: tempDir, - MaxBytes: testBytes, - duration: 24 * time.Hour, + MaxBytes: 10, MaxFiles: -1, } logFile.Write([]byte("[INFO] Hello World")) logFile.Write([]byte("[INFO] Second File")) logFile.Write([]byte("[INFO] Third File")) - want := 1 - tempFiles, _ := ioutil.ReadDir(tempDir) - if got := tempFiles; len(got) != want { - t.Errorf("Expected %d files, got %v file(s)", want, len(got)) - return - } + require.Len(t, listDir(t, tempDir), 1) +} + +func listDir(t *testing.T, name string) []string { + t.Helper() + fh, err := os.Open(name) + require.NoError(t, err) + files, err := fh.Readdirnames(100) + require.NoError(t, err) + return files } diff --git a/logging/logger.go b/logging/logger.go index a528c92796..dfc05785cf 100644 --- a/logging/logger.go +++ b/logging/logger.go @@ -40,15 +40,8 @@ type Config struct { LogRotateMaxFiles int } -const ( - // defaultRotateDuration is the default time taken by the agent to rotate logs - defaultRotateDuration = 24 * time.Hour -) - -var ( - logRotateDuration time.Duration - logRotateBytes int -) +// defaultRotateDuration is the default time taken by the agent to rotate logs +const defaultRotateDuration = 24 * time.Hour type LogSetupErrorFn func(string) @@ -86,28 +79,22 @@ func Setup(config Config, out io.Writer) (hclog.InterceptLogger, error) { // Create a file logger if the user has specified the path to the log file if config.LogFilePath != "" { dir, fileName := filepath.Split(config.LogFilePath) - // If a path is provided but has no fileName a default is provided. if fileName == "" { fileName = "consul.log" } - // Try to enter the user specified log rotation duration first - if config.LogRotateDuration != 0 { - logRotateDuration = config.LogRotateDuration - } else { - // Default to 24 hrs if no rotation period is specified - logRotateDuration = defaultRotateDuration - } - // User specified byte limit for log rotation if one is provided - if config.LogRotateBytes != 0 { - logRotateBytes = config.LogRotateBytes + if config.LogRotateDuration == 0 { + config.LogRotateDuration = defaultRotateDuration } logFile := &LogFile{ fileName: fileName, logPath: dir, - duration: logRotateDuration, - MaxBytes: logRotateBytes, + duration: config.LogRotateDuration, + MaxBytes: config.LogRotateBytes, MaxFiles: config.LogRotateMaxFiles, } + if err := logFile.pruneFiles(); err != nil { + return nil, fmt.Errorf("Failed to prune log files: %w", err) + } if err := logFile.openNew(); err != nil { return nil, fmt.Errorf("Failed to setup logging: %w", err) }